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

["Jörg Krause" <joerg.krause@embedded.rocks>]

[-- 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