UBIFS assert failed in ubifs_dirty_inode

[Jeff Angielski <jeff@theptrgroup.com>]

I am trying use an UBIFS root filesystem on my PowerPC MPC8544 but I am 
seeing some intermitent problems with "UBIFS assert failed in 
ubifs_dirty_inode" errors.

On the first boot after I program the NAND with a fresh UBI image, 
everything seems to work ok.

After that, on subsequent powercycles or reboots, I sometimes see a boot 
with the following error:

[    5.984232] UBIFS assert failed in ubifs_dirty_inode at 377 (pid 1011)

If that message occurs, in less than 1 or 2 minutes, the system is 
unresponsive and I start to see infinite messages of:

[   55.072791] UBIFS assert failed in ubifs_release_budget at 566 (pid 974)
[   55.079502] Call Trace:
[   55.081960] [df187ce0] [c00070f8] show_stack+0x3c/0x17c (unreliable)
[   55.088334] [df187d20] [c0196a44] ubifs_release_budget+0x3e0/0x5d0
[   55.094533] [df187d30] [c01752d4] release_existing_page_budget+0x30/0x40
[   55.101241] [df187d60] [c01765ac] do_writepage+0xd0/0x1e4
[   55.106652] [df187da0] [c00786e0] __writepage+0x24/0x80
[   55.111884] [df187db0] [c0078b14] write_cache_pages+0x184/0x310
[   55.117817] [df187e50] [c00c5cb0] writeback_single_inode+0xac/0x288
[   55.124092] [df187e80] [c00c6608] writeback_inodes_wb+0x2d4/0x458
[   55.130193] [df187ed0] [c00c68b8] wb_writeback+0x12c/0x200
[   55.135686] [df187f40] [c00c6cb0] wb_do_writeback+0x224/0x244
[   55.141439] [df187f80] [c00c6d38] bdi_writeback_task+0x68/0xa8
[   55.147282] [df187fa0] [c0086430] bdi_start_fn+0x80/0x104
[   55.152691] [df187fc0] [c0050cc4] kthread+0x78/0x7c
[   55.157581] [df187ff0] [c000fac8] kernel_thread+0x4c/0x68
[   55.163362] UBIFS assert failed in ubifs_budget_space at 463 (pid 1139)
[   55.169984] Call Trace:
[   55.172427] [df19dcf0] [c00070f8] show_stack+0x3c/0x17c (unreliable)
[   55.178795] [df19dd30] [c019735c] ubifs_budget_space+0x650/0xa30
[   55.184818] [df19dd90] [c01753dc] ubifs_aio_write+0xb0/0x1e8
[   55.190488] [df19ddf0] [c00a41e8] do_sync_readv_writev+0xa0/0x114
[   55.196588] [df19de90] [c00a49e0] do_readv_writev+0xb4/0x1d8
[   55.202255] [df19df10] [c00a5658] sys_writev+0x4c/0x90
[   55.207401] [df19df40] [c000fd48] ret_from_syscall+0x0/0x3c
[   55.213212] UBIFS assert failed in ubifs_release_budget at 566 (pid 1139)
[   55.220007] Call Trace:
[   55.222459] [df19dd10] [c00070f8] show_stack+0x3c/0x17c (unreliable)
[   55.228834] [df19dd50] [c0196a44] ubifs_release_budget+0x3e0/0x5d0
[   55.235027] [df19dd60] [c01752d4] release_existing_page_budget+0x30/0x40
[   55.241736] [df19dd90] [c01765ac] do_writepage+0xd0/0x1e4
[   55.247144] [df19ddd0] [c00786e0] __writepage+0x24/0x80
[   55.252376] [df19dde0] [c0078b14] write_cache_pages+0x184/0x310
[   55.258303] [df19de80] [c0072294] __filemap_fdatawrite_range+0x7c/0x90
[   55.264843] [df19dee0] [c00722fc] filemap_write_and_wait_range+0x54/0x98
[   55.271550] [df19df00] [c00ca844] vfs_fsync_range+0x60/0xc4
[   55.277129] [df19df20] [c00ca94c] do_fsync+0x30/0x54
[   55.282101] [df19df40] [c000fd48] ret_from_syscall+0x0/0x3c
[   55.287712] UBIFS assert failed in ubifs_release_budget at 566 (pid 974)
[   55.294416] Call Trace:
[   55.296865] [df187db0] [c00070f8] show_stack+0x3c/0x17c (unreliable)
[   55.303232] [df187df0] [c0196a44] ubifs_release_budget+0x3e0/0x5d0
[   55.309420] [df187e00] [c0196c74] 
ubifs_release_dirty_inode_budget+0x40/0x50
[   55.316475] [df187e30] [c017e360] ubifs_write_inode+0xb0/0x1d4
[   55.322320] [df187e50] [c00c5e3c] writeback_single_inode+0x238/0x288
[   55.328680] [df187e80] [c00c6608] writeback_inodes_wb+0x2d4/0x458
[   55.334781] [df187ed0] [c00c68b8] wb_writeback+0x12c/0x200
[   55.340274] [df187f40] [c00c6cb0] wb_do_writeback+0x224/0x244
[   55.346027] [df187f80] [c00c6d38] bdi_writeback_task+0x68/0xa8
[   55.351869] [df187fa0] [c0086430] bdi_start_fn+0x80/0x104
[   55.357277] [df187fc0] [c0050cc4] kthread+0x78/0x7c

... Goes on forever, or at least the target becomes unresponsive and I 
need to power cycle.

It occurs in both the DENX 2.6.31 and the DENX 2.6.33-rc4 (which was 
merged the infradead kernel on December 10th).

I have the latest and greatest mtd-utils which I needed to fix my 
ubiformat problem.

It occurs no matter whether I ubiformat an ubi image on the target or 
whether I install the rootfs via untaring to a ubifs mount point.

Here are the boot messages of one where the ubifs fails:


[    0.000000] Using theCore machine description
[    0.000000] Memory CAM mapping: 256/256 Mb, residual: 0Mb
[    0.000000] Linux version 2.6.33-rc4 (user@ubuntu) (gcc version 
4.2.2) #1 PREEMPT Thu Jan 21 20:03:54 EST 2010
[    0.000000] bootconsole [udbg0] enabled 

setup_arch: bootmem 

thecore_setup_arch() 

[    0.000000] Found FSL PCI host bridge at 0x00000000e0008000. Firmware 
bus number: 0->0
[    0.000000] PCI host bridge /pci@e0008000 (primary) ranges: 

[    0.000000]  MEM 0x00000000c0000000..0x00000000dfffffff -> 
0x00000000c0000000
[    0.000000] /pci@e0008000: PCICSRBAR @ 0xfff00000 

arch: exit 

[    0.000000] Zone PFN ranges: 

[    0.000000]   DMA      0x00000000 -> 0x00020000 

[    0.000000]   Normal   0x00020000 -> 0x00020000 

[    0.000000] Movable zone start PFN for each node 

[    0.000000] early_node_map[1] active PFN ranges 

[    0.000000]     0: 0x00000000 -> 0x00020000 

[    0.000000] MMU: Allocated 1088 bytes of context maps for 255 
contexts
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on. 
Total pages: 130048
[    0.000000] Kernel command line: ubi.mtd=8 root=ubi0:fs1 rw 
rootfstype=ubifs 
ip=192.168.0.251:192.168.0.61:192.168.0.61:255.255.0.0:thecore:eth0:off 
console=ttyS0,115200
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes) 
 

[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 
bytes) 

[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 
bytes) 

[    0.000000] Memory: 514560k/524288k available (4564k kernel code, 
9396k reserved, 152k data, 124k bss, 152k init) 

[    0.000000] Kernel virtual memory layout: 
 

[    0.000000]   * 0xfffdf000..0xfffff000  : fixmap 
 

[    0.000000]   * 0xfdffc000..0xfe000000  : early ioremap 
 

[    0.000000]   * 0xe1000000..0xfdffc000  : vmalloc & ioremap 
 

[    0.000000] SLUB: Genslabs=13, HWalign=32, Order=0-3, MinObjects=0, 
CPUs=1, Nodes=1 

[    0.000000] Hierarchical RCU implementation. 
 

[    0.000000] NR_IRQS:512 nr_irqs:512 
 

[    0.000000] mpic: Setting up MPIC " OpenPIC  " version 1.2 at 
e0040000, max 1 CPUs 

[    0.000000] mpic: ISU size: 80, shift: 7, mask: 7f 
 

[    0.000000] mpic: Initializing for 80 sources 
 

[    0.000000] clocksource: timebase mult[5000000] shift[22] registered 
 

[    0.000000] Console: colour dummy device 80x25 
 

[    0.010749] Mount-cache hash table entries: 512 
 

[    0.016754] NET: Registered protocol family 16 
 

 
 

[    0.023479] PCI: Probing PCI hardware 
 

[    0.027190] PCI: I/O resource not set for host bridge /pci@e0008000 
(domain 0) 

[    0.040419] bio: create slab <bio-0> at 0 
 

[    0.044938] vgaarb: loaded 
 

[    0.047926] SCSI subsystem initialized 
 

[    0.052046] usbcore: registered new interface driver usbfs 
 

[    0.057642] usbcore: registered new interface driver hub 
 

[    0.062999] usbcore: registered new device driver usb 
 

[    0.068417] Switching to clocksource timebase 
 

[    0.073628] NET: Registered protocol family 2 
 

[    0.078052] IP route cache hash table entries: 4096 (order: 2, 16384 
bytes) 

[    0.085376] TCP established hash table entries: 16384 (order: 5, 
131072 bytes) 

[    0.092728] TCP bind hash table entries: 16384 (order: 4, 65536 
bytes) 

[    0.099268] TCP: Hash tables configured (established 16384 bind 
16384) 

[    0.105707] TCP reno registered 
 

[    0.108834] UDP hash table entries: 256 (order: 0, 4096 bytes) 
 

[    0.114655] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes) 
 

[    0.121016] NET: Registered protocol family 1 
 

[    0.125490] RPC: Registered udp transport module. 
 

[    0.130165] RPC: Registered tcp transport module. 
 

[    0.134794] RPC: Registered tcp NFSv4.1 backchannel transport module. 
 

[    0.152607] squashfs: version 4.0 (2009/01/31) Phillip Lougher 
 

[    0.159456] JFFS2 version 2.2. (NAND) ?© 2001-2006 Red Hat, Inc. 
 

[    0.165994] msgmni has been set to 1005 
 

[    0.170026] io scheduler noop registered 
 

[    0.173876] io scheduler deadline registered 
 

[    0.178439] io scheduler cfq registered (default) 
 

[    0.279675] Generic RTC Driver v1.07 
 

[    0.283397] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled 
 

[    0.291300] serial8250.0: ttyS0 at MMIO 0xe0004500 (irq = 42) is a 
16550A 

[    0.298039] console [ttyS0] enabled, bootconsole disabled 
 

[    0.298039] console [ttyS0] enabled, bootconsole disabled 
 

[    0.309463] serial8250.0: ttyS1 at MMIO 0xe0004600 (irq = 42) is a 
16550A 

[    0.320944] brd: module loaded 
 

[    0.326258] loop: module loaded 
 

[    0.332367] f8000000.nor: Found 1 x16 devices at 0x0 in 16-bit bank 
 

[    0.338727]  Amd/Fujitsu Extended Query Table at 0x0040 
 

[    0.343971] f8000000.nor: CFI does not contain boot bank location. 
Assuming top. 

[    0.351368] number of CFI chips: 1 
 

[    0.354910] RedBoot partition parsing not available 
 

[    0.359830] Creating 8 MTD partitions on "f8000000.nor": 
 

[    0.365146] 0x000000000000-0x000000020000 : "config" 
 

[    0.370900] 0x000000020000-0x000000280000 : "kernel" 
 

[    0.376521] 0x000000280000-0x0000002a0000 : "fdt" 
 

[    0.381879] 0x0000002a0000-0x0000008a0000 : "tinyfs" 
 

[    0.387502] 0x0000008a0000-0x000007f40000 : "rootfs" 
 

[    0.393163] 0x000007f40000-0x000007f60000 : "u-boot-env-r" 
 

[    0.399312] 0x000007f60000-0x000007f80000 : "u-boot-env" 
 

[    0.405300] 0x000007f80000-0x000008000000 : "u-boot" 
 

[    0.411185] NAND device: Manufacturer ID: 0x2c, Chip ID: 0xd3 (Micron 
NAND 1GiB 3,3V 8-bit) 

[    0.419580] Scanning device for bad blocks 
 

[    0.429316] Bad eraseblock 72 at 0x000001200000 
 

[    0.500043] Bad eraseblock 930 at 0x00000e880000 
 

[    0.575322] Bad eraseblock 1846 at 0x00001cd80000 
 

[    0.650842] Bad eraseblock 2764 at 0x00002b300000 
 

[    0.690347] Bad eraseblock 3215 at 0x0000323c0000 
 

[    0.715104] Bad eraseblock 3475 at 0x0000364c0000 
 

[    0.727215] Bad eraseblock 3571 at 0x000037cc0000 
 

[    0.772356] Creating 2 MTD partitions on "f4000000.nand": 
 

[    0.777757] 0x000000000000-0x000020000000 : "fs1" 
 

[    0.783226] 0x000020000000-0x000040000000 : "fs2" 
 

[    0.789135] UBI: attaching mtd8 to ubi0 
 

[    0.793054] UBI: physical eraseblock size:   262144 bytes (256 KiB) 
 

[    0.799321] UBI: logical eraseblock size:    258048 bytes 
 

[    0.804719] UBI: smallest flash I/O unit:    4096 
 

[    0.809421] UBI: sub-page size:              1024 
 

[    0.814124] UBI: VID header offset:          1024 (aligned 1024) 
 

[    0.820129] UBI: data offset:                4096 
 

[    1.899933] UBI: attached mtd8 to ubi0 
 

[    1.903706] UBI: MTD device name:            "fs1" 
 

[    1.908496] UBI: MTD device size:            512 MiB 
 

[    1.913460] UBI: number of good PEBs:        2045 
 

[    1.918163] UBI: number of bad PEBs:         3 
 

[    1.922605] UBI: max. allowed volumes:       128 
 

[    1.927220] UBI: wear-leveling threshold:    4096 
 

[    1.931922] UBI: number of internal volumes: 1 
 

[    1.936364] UBI: number of user volumes:     1 
 

[    1.940806] UBI: available PEBs:             0 
 

[    1.945247] UBI: total number of reserved PEBs: 2045 
 

[    1.950210] UBI: number of PEBs reserved for bad PEB handling: 20 
 

[    1.956302] UBI: max/mean erase counter: 31/18 
 

[    1.960745] UBI: image sequence number: 86187995 
 

[    1.965428] UBI: background thread "ubi_bgt0d" started, PID 918 
 

[    1.972655] eth0: Gianfar Ethernet Controller Version 1.2, 
00:11:44:00:00:00 

[    1.979722] eth0: Running with NAPI enabled 
 

[    1.983905] eth0: :RX BD ring size for Q[0]: 256 
 

[    1.988522] eth0:TX BD ring size for Q[0]: 256 
 

[    1.993730] eth1: Gianfar Ethernet Controller Version 1.2, 
00:11:44:00:80:00 

[    2.000824] eth1: Running with NAPI enabled 
 

[    2.005007] eth1: :RX BD ring size for Q[0]: 256 
 

[    2.009622] eth1:TX BD ring size for Q[0]: 256 
 

[    2.014447] Freescale PowerQUICC MII Bus: probed 
 

[    2.020076] Freescale PowerQUICC MII Bus: probed 
 

[    2.025095] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver 
 

[    2.031421] Initializing USB Mass Storage driver... 
 

[    2.036401] usbcore: registered new interface driver usb-storage 
 

[    2.042423] USB Mass Storage support registered. 
 

[    2.047239] usbcore: registered new interface driver usbserial 
 

[    2.053083] usbserial: USB Serial Driver core 
 

[    2.060270] usbcore: registered new interface driver usbhid 
 

[    2.065871] usbhid: USB HID core driver 
 

[    2.070612] TCP cubic registered 
 

[    2.073892] Initializing XFRM netlink socket 
 

[    2.078170] NET: Registered protocol family 17 
 

[    3.588981] IP-Config: Complete: 
 

[    3.592033]      device=eth0, addr=192.168.0.251, mask=255.255.0.0, 
gw=192.168.0.61, 

[    3.599723]      host=thecore, domain=, nis-domain=(none), 
 

[    3.605212]      bootserver=192.168.0.61, rootserver=192.168.0.61, 
rootpath= 

[    3.979134] UBIFS: mounted UBI device 0, volume 0, name "fs1" 
 

[    3.984903] UBIFS: file system size:   518934528 bytes (506772 KiB, 
494 MiB, 2011 LEBs) 

[    3.992908] UBIFS: journal size:       9420800 bytes (9200 KiB, 8 
MiB, 37 LEBs) 

[    4.000217] UBIFS: media format:       w4/r0 (latest is w4/r0) 
 

[    4.006049] UBIFS: default compressor: lzo 
 

[    4.010144] UBIFS: reserved for root:  0 bytes (0 KiB) 
 

[    4.016825] VFS: Mounted root (ubifs filesystem) on device 0:12. 
 

[    4.022851] Freeing unused kernel memory: 152k init 
 

INIT: version 2.86 booting 
 

                 Welcome to DENX Embedded Linux Environment 
 

                 Press 'I' to enter interactive startup. 
 

Timed out waiting for time change. 
 

Setting clock : Thu Jan  1 01:00:05 CET 1970 [  OK  ] 
 

Building the cache [  OK  ] 
 

Setting hostname thecore:  [  OK  ] 
 

Checking filesystems 
 

Checking all file systems. 
 

[  OK  ] 
 

Mounting local filesystems:  [  OK  ] 
 

[    5.783968] UBIFS assert failed in ubifs_dirty_inode at 377 (pid 
1011)


-- 
Jeff Angielski
The PTR Group
www.theptrgroup.com