ubi_wl_get_peb: Unable to get a free PEB from user WL pool

ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Jörg Krause]

Hi,

after updating a custom build Linux Kernel from 4.0.8 to 4.1.4 my
system fails to attach an MTD partition. Note, that everything worked
fine with Linux Kernels before 4.1.

The error message is:
	ubi_wl_get_peb: Unable to get a free PEB from user WL pool
	autoresize: cannot auto-resize volume 0

The MTD partition has a size of 36 MB. The UBIFS image is created with:
	mkfs.ubifs -v -F -m 2048 -e 124KiB -c 264 -d user -o user.ubifs

The UBI image is created with:
	ubinize -v -o data.ubi -m 2048 -p 128KiB ubinize.ini

ubinize.ini:
    [user]
    mode=ubi
    image=user.ubifs
    vol_id=0
    vol_type=dynamic
    vol_name=user
    vol_flags=autoresize


It works, if I replace the vol_flags with vol_size=32480KiB. But that's
not a final solution for me.

Any idea what is wrong here?

Best regards
Jörg Krause

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Richard Weinberger]

Jörg,

Am 05.08.2015 um 23:22 schrieb Jörg Krause:
> Hi,
> 
> after updating a custom build Linux Kernel from 4.0.8 to 4.1.4 my
> system fails to attach an MTD partition. Note, that everything worked
> fine with Linux Kernels before 4.1.

UBI Fastmap saw a lot of changes in 4.1.

> The error message is:
> 	ubi_wl_get_peb: Unable to get a free PEB from user WL pool
> 	autoresize: cannot auto-resize volume 0

Can you please share the full kernel log?
Especially I'm interested in the fastmap pool sizes.

> The MTD partition has a size of 36 MB. The UBIFS image is created with:
> 	mkfs.ubifs -v -F -m 2048 -e 124KiB -c 264 -d user -o user.ubifs
> 
> The UBI image is created with:
> 	ubinize -v -o data.ubi -m 2048 -p 128KiB ubinize.ini
> 
> ubinize.ini:
>     [user]
>     mode=ubi
>     image=user.ubifs
>     vol_id=0
>     vol_type=dynamic
>     vol_name=user
>     vol_flags=autoresize
> 
> 
> It works, if I replace the vol_flags with vol_size=32480KiB. But that's
> not a final solution for me.
> 
> Any idea what is wrong here?

Not sure. Maybe fastmap claims too much PEBs.
BTW: Are you actually using fastmap or is it just enabled in your kernel config?

Thanks,
//richard

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Jörg Krause]

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

On Mi, 2015-08-05 at 23:30 +0200, Richard Weinberger wrote:
> Jörg,
> 
> Am 05.08.2015 um 23:22 schrieb Jörg Krause:
> > Hi,
> > 
> > after updating a custom build Linux Kernel from 4.0.8 to 4.1.4 my
> > system fails to attach an MTD partition. Note, that everything 
> > worked
> > fine with Linux Kernels before 4.1.
> 
> UBI Fastmap saw a lot of changes in 4.1.
> 
> > The error message is:
> > 	ubi_wl_get_peb: Unable to get a free PEB from user WL pool
> > 	autoresize: cannot auto-resize volume 0
> 
> Can you please share the full kernel log?
> Especially I'm interested in the fastmap pool sizes.

I attached the kernel boot log.

> 
> > The MTD partition has a size of 36 MB. The UBIFS image is created 
> > with:
> > 	mkfs.ubifs -v -F -m 2048 -e 124KiB -c 264 -d user -o user.ubifs
> > 
> > The UBI image is created with:
> > 	ubinize -v -o data.ubi -m 2048 -p 128KiB ubinize.ini
> > 
> > ubinize.ini:
> >     [user]
> >     mode=ubi
> >     image=user.ubifs
> >     vol_id=0
> >     vol_type=dynamic
> >     vol_name=user
> >     vol_flags=autoresize
> > 
> > 
> > It works, if I replace the vol_flags with vol_size=32480KiB. But 
> > that's
> > not a final solution for me.
> > 
> > Any idea what is wrong here?
> 
> Not sure. Maybe fastmap claims too much PEBs.
> BTW: Are you actually using fastmap or is it just enabled in your 
> kernel config?

It is enabled in the kernel config. Not sure how to use it.

[-- Attachment #2: kernel.log --]
[-- Type: text/x-log, Size: 11285 bytes --]

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.1.4-LINTECH (joerg@nzxt) (gcc version 4.9.2 (Buildroot 2015.05-00046-gbab9d23) ) #3 PREEMPT Wed Aug 5 22:04:07 CEST 2015
[    0.000000] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=0005317f
[    0.000000] CPU: VIVT data cache, VIVT instruction cache
[    0.000000] Machine model: HBM10
[    0.000000] Memory policy: Data cache writeback
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
[    0.000000] Kernel command line: console=ttyAMA0,115200n8 mtdparts=gpmi-nand:1m(bootarea)ro,1m(uboot-0),1m(uboot-1),512k(env-0),512k(env-1),44m(ubi-0),44m(ubi-1),-(data) ubi.mtd=ubi-0 ubi.mtd=data root=ubi0:rootfs rootfstype=ubifs init=/etc/preinit
[    0.000000] PID hash table entries: 256 (order: -2, 1024 bytes)
[    0.000000] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Memory: 50632K/65536K available (4352K kernel code, 189K rwdata, 1284K rodata, 160K init, 8180K bss, 14904K reserved, 0K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xc4800000 - 0xff000000   ( 936 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xc4000000   (  64 MB)
[    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
[    0.000000]       .text : 0xc0008000 - 0xc0589488   (5638 kB)
[    0.000000]       .init : 0xc058a000 - 0xc05b2000   ( 160 kB)
[    0.000000]       .data : 0xc05b2000 - 0xc05e1520   ( 190 kB)
[    0.000000]        .bss : 0xc05e1520 - 0xc0dde8e8   (8181 kB)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Running RCU self tests
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	RCU lockdep checking is enabled.
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] clocksource mxs_timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000034] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.001969] Console: colour dummy device 80x30
[    0.002162] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.002202] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.002229] ... MAX_LOCK_DEPTH:          48
[    0.002254] ... MAX_LOCKDEP_KEYS:        8191
[    0.002278] ... CLASSHASH_SIZE:          4096
[    0.002300] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.002321] ... MAX_LOCKDEP_CHAINS:      65536
[    0.002342] ... CHAINHASH_SIZE:          32768
[    0.002363]  memory used by lock dependency info: 5167 kB
[    0.002385]  per task-struct memory footprint: 1152 bytes
[    0.002534] Calibrating delay loop... 226.09 BogoMIPS (lpj=1130496)
[    0.071381] pid_max: default: 32768 minimum: 301
[    0.072129] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.072202] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.079918] CPU: Testing write buffer coherency: ok
[    0.084088] Setting up static identity map for 0x40008400 - 0x4000843c
[    0.103232] devtmpfs: initialized
[    0.180916] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.183255] pinctrl core: initialized pinctrl subsystem
[    0.198783] NET: Registered protocol family 16
[    0.201468] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.296268] Serial: AMBA PL011 UART driver
[    0.298942] 80074000.serial: ttyAMA0 at MMIO 0x80074000 (irq = 217, base_baud = 0) is a PL011 rev2
[    0.631046] console [ttyAMA0] enabled
[    0.734071] mxs-dma 80004000.dma-apbh: initialized
[    0.750960] mxs-dma 80024000.dma-apbx: initialized
[    0.764478] SCSI subsystem initialized
[    0.771368] usbcore: registered new interface driver usbfs
[    0.777557] usbcore: registered new interface driver hub
[    0.783926] usbcore: registered new device driver usb
[    0.790908] pps_core: LinuxPPS API ver. 1 registered
[    0.796076] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.805534] PTP clock support registered
[    0.812673] Advanced Linux Sound Architecture Driver Initialized.
[    0.834663] cfg80211: Calling CRDA to update world regulatory domain
[    0.842645] Switched to clocksource mxs_timer
[    0.853273] FS-Cache: Loaded
[    0.942972] NET: Registered protocol family 2
[    0.954757] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.962103] TCP bind hash table entries: 1024 (order: 3, 36864 bytes)
[    0.969678] TCP: Hash tables configured (established 1024 bind 1024)
[    0.976755] UDP hash table entries: 256 (order: 2, 20480 bytes)
[    0.983415] UDP-Lite hash table entries: 256 (order: 2, 20480 bytes)
[    0.992337] NET: Registered protocol family 1
[    1.006574] futex hash table entries: 256 (order: 1, 11264 bytes)
[    1.089972] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    1.107920] io scheduler noop registered
[    1.111986] io scheduler deadline registered (default)
[    1.126181] 8006a000.serial: ttyAPP0 at MMIO 0x8006a000 (irq = 216, base_baud = 1500000) is a 8006a000.serial
[    1.138907] mxs-auart 8006a000.serial: Found APPUART 3.1.0
[    1.156861] nand: device found, Manufacturer ID: 0x98, Chip ID: 0xd1
[    1.163615] nand: Toshiba NAND 128MiB 3,3V 8-bit
[    1.168303] nand: 128 MiB, SLC, erase size: 128 KiB, page size: 2048, OOB size: 64
[    1.176321] Scanning device for bad blocks
[    1.691736] 8 cmdlinepart partitions found on MTD device gpmi-nand
[    1.698116] Creating 8 MTD partitions on "gpmi-nand":
[    1.703405] 0x000000000000-0x000000100000 : "bootarea"
[    1.714550] 0x000000100000-0x000000200000 : "uboot-0"
[    1.723032] 0x000000200000-0x000000300000 : "uboot-1"
[    1.731396] 0x000000300000-0x000000380000 : "env-0"
[    1.739509] 0x000000380000-0x000000400000 : "env-1"
[    1.747783] 0x000000400000-0x000003000000 : "ubi-0"
[    1.756140] 0x000003000000-0x000005c00000 : "ubi-1"
[    1.764477] 0x000005c00000-0x000008000000 : "data"
[    1.772887] gpmi-nand 8000c000.gpmi-nand: driver registered.
[    1.915269] libphy: fec_enet_mii_bus: probed
[    1.926575] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.934308] usbcore: registered new interface driver usb-storage
[    1.967053] stmp3xxx-rtc 80056000.rtc: rtc core: registered 80056000.rtc as rtc0
[    1.976118] i2c /dev entries driver
[    1.984726] stmp3xxx_rtc_wdt stmp3xxx_rtc_wdt: initialized watchdog with heartbeat 19s
[    2.032982] mxs-mmc 80014000.ssp: initialized
[    2.067296] usbcore: registered new interface driver usbhid
[    2.073433] usbhid: USB HID core driver
[    2.107226] mmc0: new high speed SDIO card at address 0001
[    2.128583] mxs-wm8524 sound: wm8524-hifi <-> 80042000.saif mapping ok
[    2.136388] mxs-wm8524 sound: wm8524-hifi <-> 80046000.saif mapping ok
[    2.159350] ipip: IPv4 over IPv4 tunneling driver
[    2.175604] NET: Registered protocol family 10
[    2.193551] sit: IPv6 over IPv4 tunneling driver
[    2.204237] NET: Registered protocol family 17
[    2.210472] Key type dns_resolver registered
[    2.220794] registered taskstats version 1
[    2.235005] ubi0: default fastmap pool size: 15
[    2.239602] ubi0: default fastmap WL pool size: 7
[    2.244822] ubi0: attaching mtd5
[    3.075916] ubi0: scanning is finished
[    3.107807] ubi0 warning: print_rsvd_warning: cannot reserve enough PEBs for bad PEB handling, reserved 18, need 20
[    3.136509] ubi0: attached mtd5 (name "ubi-0", size 44 MiB)
[    3.142148] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    3.149309] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    3.156278] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
[    3.163403] ubi0: good PEBs: 352, bad PEBs: 0, corrupted PEBs: 0
[    3.169462] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128
[    3.176838] ubi0: max/mean erase counter: 1/0, WL threshold: 4096, image sequence number: 1409686509
[    3.186128] ubi0: available PEBs: 0, total reserved PEBs: 352, PEBs reserved for bad PEB handling: 18
[    3.195855] ubi0: background thread "ubi_bgt0d" started, PID 41
[    3.202421] ubi1: default fastmap pool size: 10
[    3.207174] ubi1: default fastmap WL pool size: 5
[    3.211950] ubi1: attaching mtd7
[    3.570120] ubi1: scanning is finished
[    3.608408] ubi1 error: ubi_wl_get_peb: Unable to get a free PEB from user WL pool
[    3.616304] ubi1 error: autoresize: cannot auto-resize volume 0
[    3.625328] UBI error: cannot attach mtd7
[    3.636199] input: gpio-keys as /devices/soc0/gpio-keys/input/input0
[    3.645160] random: nonblocking pool is initialized
[    3.656902] stmp3xxx-rtc 80056000.rtc: setting system clock to 1970-01-01 00:01:20 UTC (80)
[    3.720212] ALSA device list:
[    3.723413]   #0: mxs_wm8524
[    3.730930] uart-pl011 80074000.serial: no DMA platform data
[    4.014974] cfg80211: Calling CRDA to update world regulatory domain
[    4.034577] UBIFS (ubi0:1): UBIFS: mounted UBI device 0, volume 1, name "rootfs", R/O mode
[    4.043245] UBIFS (ubi0:1): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
[    4.053361] UBIFS (ubi0:1): FS size: 40378368 bytes (38 MiB, 318 LEBs), journal size 5586944 bytes (5 MiB, 44 LEBs)
[    4.063960] UBIFS (ubi0:1): reserved for root: 0 bytes (0 KiB)
[    4.069859] UBIFS (ubi0:1): media format: w4/r0 (latest is w4/r0), UUID 3F6F3705-5F75-41A9-98C0-9FFF1CC2B9FB, small LPT model
[    4.091395] VFS: Mounted root (ubifs filesystem) readonly on device 0:13.
[    4.108972] devtmpfs: mounted
[    4.113768] Freeing unused kernel memory: 160K (c058a000 - c05b2000)
[    4.526339] UBIFS error (pid: 42): cannot open "/dev/ubi1_0", error -22mount: mounting /dev/ubi1_0 on /mnt/user failed: Invalid argument
mkdir: can't create directory '/mnt/user/overlay': Read-only file system
mkdir: can't create directory '/mnt/user/work': Read-only file system

[    4.642034] overlayfs: failed to resolve '/mnt/user/overlay': -2
mount: mounting overlay on /mnt/overlay failed: No such file or directory
mount: mounting /dev on /mnt/overlay/dev failed: No such file or directory
mount: mounting /mnt/user on /mnt/overlay/mnt/user failed: No such file or directory
chroot: can't execute '/sbin/init': No such file or directory
[    4.728498] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00
[    4.728498] 
[    4.737710] CPU: 0 PID: 1 Comm: chroot Not tainted 4.1.4-LINTECH #3
[    4.744005] Hardware name: Freescale MXS (Device Tree)
[    4.749232] [<c000eacc>] (unwind_backtrace) from [<c000ce34>] (show_stack+0x10/0x14)
[    4.757044] [<c000ce34>] (show_stack) from [<c041f9bc>] (panic+0x98/0x200)
[    4.763988] [<c041f9bc>] (panic) from [<c00188bc>] (do_exit+0x89c/0x8d4)
[    4.770742] [<c00188bc>] (do_exit) from [<c0019cd4>] (do_group_exit+0x3c/0xbc)
[    4.778020] [<c0019cd4>] (do_group_exit) from [<c0019d64>] (__wake_up_parent+0x0/0x18)
[    4.786141] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Richard Weinberger]

Jörg,

Am 05.08.2015 um 23:38 schrieb Jörg Krause:
> On Mi, 2015-08-05 at 23:30 +0200, Richard Weinberger wrote:
>> Jörg,
>>
>> Am 05.08.2015 um 23:22 schrieb Jörg Krause:
>>> Hi,
>>>
>>> after updating a custom build Linux Kernel from 4.0.8 to 4.1.4 my
>>> system fails to attach an MTD partition. Note, that everything 
>>> worked
>>> fine with Linux Kernels before 4.1.
>>
>> UBI Fastmap saw a lot of changes in 4.1.
>>
>>> The error message is:
>>> 	ubi_wl_get_peb: Unable to get a free PEB from user WL pool
>>> 	autoresize: cannot auto-resize volume 0
>>
>> Can you please share the full kernel log?
>> Especially I'm interested in the fastmap pool sizes.
> 
> I attached the kernel boot log.

Thanks.
That's a really small UBI setup.
[    3.202421] ubi1: default fastmap pool size: 10
[    3.207174] ubi1: default fastmap WL pool size: 5

>>
>>> The MTD partition has a size of 36 MB. The UBIFS image is created 
>>> with:
>>> 	mkfs.ubifs -v -F -m 2048 -e 124KiB -c 264 -d user -o user.ubifs
>>>
>>> The UBI image is created with:
>>> 	ubinize -v -o data.ubi -m 2048 -p 128KiB ubinize.ini
>>>
>>> ubinize.ini:
>>>     [user]
>>>     mode=ubi
>>>     image=user.ubifs
>>>     vol_id=0
>>>     vol_type=dynamic
>>>     vol_name=user
>>>     vol_flags=autoresize
>>>
>>>
>>> It works, if I replace the vol_flags with vol_size=32480KiB. But 
>>> that's
>>> not a final solution for me.
>>>
>>> Any idea what is wrong here?
>>
>> Not sure. Maybe fastmap claims too much PEBs.
>> BTW: Are you actually using fastmap or is it just enabled in your 
>> kernel config?
> 
> It is enabled in the kernel config. Not sure how to use it.

Then just disable it. :)
Meanwhile I'll find out what exactly is going on.

Thanks,
//richard

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Jörg Krause]

On Mi, 2015-08-05 at 23:45 +0200, Richard Weinberger wrote:
> Jörg,
> 
> Am 05.08.2015 um 23:38 schrieb Jörg Krause:
> > On Mi, 2015-08-05 at 23:30 +0200, Richard Weinberger wrote:

[snip]

> > 
> > I attached the kernel boot log.
> 
> Thanks.
> That's a really small UBI setup.
> [    3.202421] ubi1: default fastmap pool size: 10
> [    3.207174] ubi1: default fastmap WL pool size: 5

What do you exactly mean by small UBI setup? The fastmap pool size? The
UBI layout?

[snip]

> > 
> > It is enabled in the kernel config. Not sure how to use it.
> 
> Then just disable it. :)

I did :) I thought fastmap is used automatically by the UBI driver?

> Meanwhile I'll find out what exactly is going on.

Many thanks!

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Richard Weinberger]

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

Am 05.08.2015 um 23:53 schrieb Jörg Krause:
> On Mi, 2015-08-05 at 23:45 +0200, Richard Weinberger wrote:
>> Jörg,
>>
>> Am 05.08.2015 um 23:38 schrieb Jörg Krause:
>>> On Mi, 2015-08-05 at 23:30 +0200, Richard Weinberger wrote:
> 
> [snip]
> 
>>>
>>> I attached the kernel boot log.
>>
>> Thanks.
>> That's a really small UBI setup.
>> [    3.202421] ubi1: default fastmap pool size: 10
>> [    3.207174] ubi1: default fastmap WL pool size: 5
> 
> What do you exactly mean by small UBI setup? The fastmap pool size? The
> UBI layout?

The UBI image it self. Your MTD is very small.
But it should not matter.

> [snip]
> 
>>>
>>> It is enabled in the kernel config. Not sure how to use it.
>>
>> Then just disable it. :)
> 
> I did :) I thought fastmap is used automatically by the UBI driver?

It will *use* fastmap automatically but not convert non-fastmap UBI images
to fastmap.
You can enable ubi.fm_autoconvert to do so.

>> Meanwhile I'll find out what exactly is going on.
> 
> Many thanks!

Can you please apply the attached debug patch?
I wonder why exactly the auto resize function is failing.

Thanks,
//richard

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: debug.diff --]
[-- Type: text/x-patch; name="debug.diff", Size: 1012 bytes --]

diff --git a/drivers/mtd/ubi/build.c b/drivers/mtd/ubi/build.c
index 22fd19c..89aa7ac9 100644
--- a/drivers/mtd/ubi/build.c
+++ b/drivers/mtd/ubi/build.c
@@ -820,8 +820,8 @@ static int autoresize(struct ubi_device *ubi, int vol_id)
 		err = ubi_resize_volume(&desc,
 					old_reserved_pebs + ubi->avail_pebs);
 		if (err)
-			ubi_err(ubi, "cannot auto-resize volume %d",
-				vol_id);
+			ubi_err(ubi, "cannot auto-resize volume %d: %d",
+				vol_id, err);
 	}
 
 	if (err)
diff --git a/drivers/mtd/ubi/vmt.c b/drivers/mtd/ubi/vmt.c
index 1ae17bb..7be6fa3 100644
--- a/drivers/mtd/ubi/vmt.c
+++ b/drivers/mtd/ubi/vmt.c
@@ -498,8 +498,10 @@ int ubi_resize_volume(struct ubi_volume_desc *desc, int reserved_pebs)
 	if (pebs < 0) {
 		for (i = 0; i < -pebs; i++) {
 			err = ubi_eba_unmap_leb(ubi, vol, reserved_pebs + i);
-			if (err)
+			if (err) {
+				ubi_err(ubi, "unable to unmap LEB");
 				goto out_acc;
+			}
 		}
 		spin_lock(&ubi->volumes_lock);
 		ubi->rsvd_pebs += pebs;

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Jörg Krause]

On Do, 2015-08-06 at 00:01 +0200, Richard Weinberger wrote:
> Am 05.08.2015 um 23:53 schrieb Jörg Krause:
> > On Mi, 2015-08-05 at 23:45 +0200, Richard Weinberger wrote:
> > > Jörg,
> > > 
> > > Am 05.08.2015 um 23:38 schrieb Jörg Krause:
> > > > On Mi, 2015-08-05 at 23:30 +0200, Richard Weinberger wrote:
> > 
> > [snip]
> > 
> > > > 
> > > > I attached the kernel boot log.
> > > 
> > > Thanks.
> > > That's a really small UBI setup.
> > > [    3.202421] ubi1: default fastmap pool size: 10
> > > [    3.207174] ubi1: default fastmap WL pool size: 5
> > 
> > What do you exactly mean by small UBI setup? The fastmap pool size? 
> > The
> > UBI layout?
> 
> The UBI image it self. Your MTD is very small.
> But it should not matter.
> 
> > [snip]
> > 
> > > > 
> > > > It is enabled in the kernel config. Not sure how to use it.
> > > 
> > > Then just disable it. :)
> > 
> > I did :) I thought fastmap is used automatically by the UBI driver?
> 
> It will *use* fastmap automatically but not convert non-fastmap UBI 
> images
> to fastmap.
> You can enable ubi.fm_autoconvert to do so.

Sorry for asking, but how do I create an UBI image with fastmap
support? I've never read something about this.

> > > Meanwhile I'll find out what exactly is going on.
> > 
> > Many thanks!
> 
> Can you please apply the attached debug patch?
> I wonder why exactly the auto resize function is failing.

autoresize: cannot auto-resize volume 0: -28

Jörg

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Richard Weinberger]

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

Jörg,

Am 06.08.2015 um 00:17 schrieb Jörg Krause:
>>>> Then just disable it. :)
>>>
>>> I did :) I thought fastmap is used automatically by the UBI driver?
>>
>> It will *use* fastmap automatically but not convert non-fastmap UBI 
>> images
>> to fastmap.
>> You can enable ubi.fm_autoconvert to do so.
> 
> Sorry for asking, but how do I create an UBI image with fastmap
> support? I've never read something about this.

You have to use the ubi.fm_autoconvert parameter. The UBI will automatically
write down a fastmap if needed.

Currently it is not possible to create a fastmap-enabled UBI image
using ubinize.
The reason is that fastmap stores the LEB->PEB mappings to allow
a fast attach. ubinize cannot know which PEBs are bad.
So, we'd need a tool which creates the fastmap while flashing to the nand.

>>>> Meanwhile I'll find out what exactly is going on.
>>>
>>> Many thanks!
>>
>> Can you please apply the attached debug patch?
>> I wonder why exactly the auto resize function is failing.
> 
> autoresize: cannot auto-resize volume 0: -28

I have good and bad news.
The good news is that I know what is going on, the bad one
is that I don't have an good solution for it.

UBI is requesting a new PEB but your system is still busy with
erasing them. With fastmap disabled UBI can use produce_free_peb()
and wait for a new erased PEB.
But fastmap cannot use this helper as it releases ->wl_lock
and would lead to a inconsistent fastmap state.
Kernels < 4.1 did so and faced interesting fastmap corruptions.
I hoped using the current retry logic the issue you're facing cannot
happen. But as it seems I was wrong.

Can you please give the attached patch a try?

Thanks,
//richard

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: dirty_hack.diff --]
[-- Type: text/x-patch; name="dirty_hack.diff", Size: 509 bytes --]

diff --git a/drivers/mtd/ubi/fastmap-wl.c b/drivers/mtd/ubi/fastmap-wl.c
index b2a6653..e47974d 100644
--- a/drivers/mtd/ubi/fastmap-wl.c
+++ b/drivers/mtd/ubi/fastmap-wl.c
@@ -206,12 +206,12 @@ again:
 
 	if (pool->used == pool->size) {
 		spin_unlock(&ubi->wl_lock);
-		if (retried) {
+		if (retried > 5) {
 			ubi_err(ubi, "Unable to get a free PEB from user WL pool");
 			ret = -ENOSPC;
 			goto out;
 		}
-		retried = 1;
+		retried++;
 		up_read(&ubi->fm_eba_sem);
 		goto again;
 	}

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Jörg Krause]

On Do, 2015-08-06 at 09:30 +0200, Richard Weinberger wrote:
> Jörg,
> 
> Am 06.08.2015 um 00:17 schrieb Jörg Krause:
> > > > > Then just disable it. :)
> > > > 
> > > > I did :) I thought fastmap is used automatically by the UBI 
> > > > driver?
> > > 
> > > It will *use* fastmap automatically but not convert non-fastmap 
> > > UBI 
> > > images
> > > to fastmap.
> > > You can enable ubi.fm_autoconvert to do so.
> > 
> > Sorry for asking, but how do I create an UBI image with fastmap
> > support? I've never read something about this.
> 
> You have to use the ubi.fm_autoconvert parameter. The UBI will 
> automatically
> write down a fastmap if needed.
> 
> Currently it is not possible to create a fastmap-enabled UBI image
> using ubinize.
> The reason is that fastmap stores the LEB->PEB mappings to allow
> a fast attach. ubinize cannot know which PEBs are bad.
> So, we'd need a tool which creates the fastmap while flashing to the 
> nand.
> 

I see!

> > > > > Meanwhile I'll find out what exactly is going on.
> > > > 
> > > > Many thanks!
> > > 
> > > Can you please apply the attached debug patch?
> > > I wonder why exactly the auto resize function is failing.
> > 
> > autoresize: cannot auto-resize volume 0: -28
> 
> I have good and bad news.
> The good news is that I know what is going on, the bad one
> is that I don't have an good solution for it.
> 
> UBI is requesting a new PEB but your system is still busy with
> erasing them. With fastmap disabled UBI can use produce_free_peb()
> and wait for a new erased PEB.
> But fastmap cannot use this helper as it releases ->wl_lock
> and would lead to a inconsistent fastmap state.
> Kernels < 4.1 did so and faced interesting fastmap corruptions.
> I hoped using the current retry logic the issue you're facing cannot
> happen. But as it seems I was wrong.
> 
> Can you please give the attached patch a try?
> 

I tried the "dirty hack", but it does not solves the problem. I also
tested with 100 retries, but the error remains.

I will turn fastmap off for now, but feel free to send more patches to
try.

Jörg

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Richard Weinberger]

Am 06.08.2015 um 10:10 schrieb Jörg Krause:
> I tried the "dirty hack", but it does not solves the problem. I also
> tested with 100 retries, but the error remains.
> 
> I will turn fastmap off for now, but feel free to send more patches to
> try.

Okay. Maybe you're facing something completely different.
Let me cook a more advanced debug patch to find out what is going on.

LG,
//richard

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Richard Weinberger]

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

Am 06.08.2015 um 10:10 schrieb Jörg Krause:
> I will turn fastmap off for now, but feel free to send more patches to
> try.

Can you please give the attached patch a try?

Thanks,
//richard

[-- Attachment #2: fastmap_produce_peb.diff --]
[-- Type: text/x-patch, Size: 1071 bytes --]

diff --git a/drivers/mtd/ubi/fastmap-wl.c b/drivers/mtd/ubi/fastmap-wl.c
index b2a6653..bbd30dc 100644
--- a/drivers/mtd/ubi/fastmap-wl.c
+++ b/drivers/mtd/ubi/fastmap-wl.c
@@ -172,6 +172,30 @@ void ubi_refill_pools(struct ubi_device *ubi)
 }
 
 /**
+ * produce_free_peb - produce a free physical eraseblock.
+ * @ubi: UBI device description object
+ *
+ * This function tries to make a free PEB by means of synchronous execution of
+ * pending works. This may be needed if, for example the background thread is
+ * disabled. Returns zero in case of success and a negative error code in case
+ * of failure.
+ */
+static int produce_free_peb(struct ubi_device *ubi)
+{
+	int err;
+
+	while (!ubi->free.rb_node && ubi->works_count) {
+		dbg_wl("do one work synchronously");
+		err = do_work(ubi);
+
+		if (err)
+			return err;
+	}
+
+	return 0;
+}
+
+/**
  * ubi_wl_get_peb - get a physical eraseblock.
  * @ubi: UBI device description object
  *
@@ -213,6 +237,7 @@ again:
 		}
 		retried = 1;
 		up_read(&ubi->fm_eba_sem);
+		produce_free_peb(ubi);
 		goto again;
 	}
 

Re: ubi_wl_get_peb: Unable to get a free PEB from user WL pool

[Jörg Krause]

On Do, 2015-08-06 at 20:16 +0200, Richard Weinberger wrote:
> Am 06.08.2015 um 10:10 schrieb Jörg Krause:
> > I will turn fastmap off for now, but feel free to send more patches 
> > to
> > try.
> 
> Can you please give the attached patch a try?
> 

Congratulations! That fix it :-)

Here is the corresponding snap from the kernel log:

    [    3.175194] ubi1: default fastmap pool size: 10
    [    3.179937] ubi1: default fastmap WL pool size: 5
    [    3.184713] ubi1: attaching mtd7
    [    3.539869] ubi1: scanning is finished
    [    3.623707] ubi1: volume 0 ("user") re-sized from 13 to 262 LEBs
    [    3.634937] ubi1: attached mtd7 (name "data", size 36 MiB)
    [    3.640722] ubi1: PEB size: 131072 bytes (128 KiB), LEB size:
    126976 bytes
    [    3.647772] ubi1: min./max. I/O unit sizes: 2048/2048, sub-page
    size 2048
    [    3.654611] ubi1: VID header offset: 2048 (aligned 2048), data
    offset: 4096
    [    3.661714] ubi1: good PEBs: 288, bad PEBs: 0, corrupted PEBs: 0
    [    3.667890] ubi1: user volume: 1, internal volumes: 1, max.
    volumes count: 128
    [    3.675168] ubi1: max/mean erase counter: 1/0, WL threshold:
    4096, image sequence number: 1059544151
    [    3.684448] ubi1: available PEBs: 0, total reserved PEBs: 288,
    PEBs reserved for bad PEB handling: 20
    [    3.693923] ubi1: background thread "ubi_bgt1d" started, PID 42

Many thanks for this!

Jörg