Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
To:     Miquel Raynal <miquel.raynal@bootlin.com>,
        Richard Weinberger <richard@nod.at>
Cc:     linux-mtd <linux-mtd@lists.infradead.org>,
        "linux-arm-kernel@lists.infradead.org" 
        <linux-arm-kernel@lists.infradead.org>,
        Linux Kernel <linux-kernel@vger.kernel.org>
From:   Richard Genoud <richard.genoud@gmail.com>
Subject: fastmap WARN_ON() after ubiupdatevol
Message-ID: <7a4adbc9-2cf0-e80b-8d0c-c351bc64bd35@gmail.com>
Date:   Wed, 4 Dec 2019 12:14:59 +0100
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.2.2
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

Hi !

I've seen that fastmap issues a warning after updating an ubifs volume :
ubi0: default fastmap pool size: 95
ubi0: default fastmap WL pool size: 47
ubi0: attaching mtd3
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1 at drivers/mtd/ubi/fastmap.c:781 ubi_attach_fastmap+0xadc/0xc30
Modules linked in:
CPU: 0 PID: 1 Comm: swapper Not tainted 5.4.1-00048-g23479ee4c63a #1
Hardware name: Atmel AT91SAM9
Backtrace: 
[<c000e484>] (dump_backtrace) from [<c000e884>] (show_stack+0x20/0x24)
 r6:00000000 r5:c066d88c r4:00000000 r3:c4bfd525
[<c000e864>] (show_stack) from [<c04b99dc>] (dump_stack+0x20/0x28)
[<c04b99bc>] (dump_stack) from [<c0018d04>] (__warn+0xdc/0x104)
[<c0018c28>] (__warn) from [<c0018da0>] (warn_slowpath_fmt+0x74/0x80)
 r10:00000000 r8:0000030d r7:c066d88c r6:c0332144 r5:00000009 r4:00000000
[<c0018d30>] (warn_slowpath_fmt) from [<c0332144>] (ubi_attach_fastmap+0xadc/0xc30)
 r8:c71fd000 r7:c78b7d98 r6:00000000 r5:c71dcf00 r4:000007a9
[<c0331668>] (ubi_attach_fastmap) from [<c033293c>] (ubi_scan_fastmap+0x668/0x85c)
 r10:b1c9b7aa r9:00000000 r8:c71ff600 r7:00000000 r6:c8afe000 r5:b1c9b7aa
 r4:c71fd000
[<c03322d4>] (ubi_scan_fastmap) from [<c032e1f8>] (ubi_attach+0xe0/0x2a4)
 r10:00000014 r9:c71fd040 r8:00000040 r7:c71dce80 r6:c71dcf00 r5:00000000
 r4:c71fd000
[<c032e118>] (ubi_attach) from [<c03218fc>] (ubi_attach_mtd_dev+0x68c/0xb28)
 r8:c7b85000 r7:00000000 r6:c71fd000 r5:fffff800 r4:00000840 r3:00000002
[<c0321270>] (ubi_attach_mtd_dev) from [<c06fec50>] (ubi_init+0x148/0x1e8)
 r10:c07c53e4 r9:00000000 r8:c07c53e0 r7:00000000 r6:c07c53e4 r5:c7b85000
 r4:00000000
[<c06feb08>] (ubi_init) from [<c000aafc>] (do_one_initcall+0x7c/0x1e0)
 r10:c0711834 r8:00000077 r7:00000000 r6:c073258c r5:00000007 r4:c06feb08
[<c000aa80>] (do_one_initcall) from [<c06da114>] (kernel_init_freeable+0x128/0x1fc)
 r7:c7eebcc0 r6:c073258c r5:00000007 r4:00000020
[<c06d9fec>] (kernel_init_freeable) from [<c04d17d4>] (kernel_init+0x18/0x100)
 r10:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c04d17bc r4:00000000
[<c04d17bc>] (kernel_init) from [<c00090e0>] (ret_from_fork+0x14/0x34)
Exception stack(0xc78b7fb0 to 0xc78b7ff8)
7fa0:                                     00000000 00000000 00000000 00000000
7fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
7fe0: 00000000 00000000 00000000 00000000 00000013 00000000
 r4:00000000 r3:60000053
---[ end trace b00dfb7213ba31a7 ]---
ubi0 error: ubi_scan_fastmap: Attach by fastmap failed, doing a full scan!
random: fast init done
ubi0: scanning is finished
ubi0: attached mtd3 (name "ubi", size 245 MiB)
ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
ubi0: good PEBs: 1964, bad PEBs: 0, corrupted PEBs: 0
ubi0: user volume: 3, internal volumes: 1, max. volumes count: 128
ubi0: max/mean erase counter: 26/12, WL threshold: 4096, image sequence number: 1761477484
ubi0: available PEBs: 0, total reserved PEBs: 1964, PEBs reserved for bad PEB handling: 40

The corresponding code is :
	/*
	 * If fastmap is leaking PEBs (must not happen), raise a
	 * fat warning and fall back to scanning mode.
	 * We do this here because in ubi_wl_init() it's too late
	 * and we cannot fall back to scanning.
	 */
	if (WARN_ON(count_fastmap_pebs(ai) != ubi->peb_count -
		    ai->bad_peb_count - fm->used_blocks))
		goto fail_bad;

I added some debug and found that, when everything is ok, I have :
ubi_attach_fastmap: count_fastmap_pebs(ai)=1963 ubi->peb_count=1964 ai->bad_peb_count=0 fm->used_blocks=1
But when the warning rises, I have:
ubi_attach_fastmap: count_fastmap_pebs(ai)=1954 ubi->peb_count=1964 ai->bad_peb_count=0 fm->used_blocks=1
It can also be:
ubi_attach_fastmap: count_fastmap_pebs(ai)=1962 ubi->peb_count=1964 ai->bad_peb_count=0 fm->used_blocks=1
ubi_attach_fastmap: count_fastmap_pebs(ai)=1960 ubi->peb_count=1964 ai->bad_peb_count=0 fm->used_blocks=1

After a reboot, all is back to normal.

Kernel is 5.4.1, mtd-utils are 1.5.1 (yes, it's quite old)

The nand layout is :
0x000000000000-0x000010000000 : "all"
0x000000000000-0x000000020000 : "dtb"
0x000000020000-0x000000a00000 : "kernel"
0x000000a00000-0x00000ff80000 : "ubi"
0x00000ff80000-0x000010000000 : "bbt"
page size : 2KiB
subpage size : 2KiB
PEB size: 128KiB
ubi0_0 : 537 LEBs
ubi0_1 : 537 LEBs
ubi0_2 : 844 LEBs
40 PEBs reserved for bad blocks
4 PEB for UBI overhead
2 PEB for fastmap

The ubifs image is created with :
mkfs.ubifs -d dummy/ -e 0x1f000 -c 537 -m 0x800 -x lzo -o toto.ubifs
and updated with:
ubiupdatevol /dev/ubi0_0 toto.ubifs

It seems to happen only when toto.ubifs is quite big (in my case : 57520128
bytes (453 LEBs))

(I can provide the toto.ubifs if needed)

Regards,
Richard