UBI: Race between fastmap_write and wear_leveling_worker

UBI: Race between fastmap_write and wear_leveling_worker

[Anders Olofsson]

After enabling fastmap I sometimes get the following warning at boot:

[    2.612424] ubi1: default fastmap pool size: 8
[    2.616802] ubi1: default fastmap WL pool size: 4
[    2.621412] ubi1: attaching mtd3
[    2.739113] ------------[ cut here ]------------
[    2.743623] WARNING: CPU: 0 PID: 102 at drivers/mtd/ubi/fastmap.c:832 
ubi_scan_fastmap+0x145c/0x1464()
[    2.752929] Modules linked in:
[    2.755932] CPU: 0 PID: 102 Comm: ubiattach Not tainted 4.4.19 #24
[    2.762077] Stack : 80916aaa 00000036 80910000 00000000 00000000 
00000000 80095c08 8081fca7
           8fef19d8 00000066 00000000 80904f60 8f49c400 8f592000 
00000000 80095c38
           00000000 803b0078 00000002 00000000 807659f8 8f5a7c14 
8f5a7bfc 8012b6c0
           00000009 80044808 8f49c400 8f592000 8f5a7c14 00000082 
00000200 8075ccd8
           00000000 00000000 00000000 00000000 00000000 00000000 
00000000 00000000
           ...
[    2.797492] Call Trace:
[    2.799939] [<80020894>] show_stack+0x94/0xb0
[    2.804277] [<803a17d8>] dump_stack+0x88/0xc0
[    2.808633] [<8004497c>] warn_slowpath_common+0xa4/0xe0
[    2.813822] [<800449dc>] warn_slowpath_null+0x24/0x30
[    2.818860] [<80454e98>] ubi_scan_fastmap+0x145c/0x1464
[    2.824077] [<80451754>] ubi_attach+0x2e8/0x4b4
[    2.828585] [<80441400>] ubi_attach_mtd_dev+0x9f4/0x10fc
[    2.833872] [<80441e10>] ctrl_cdev_ioctl+0x100/0x204
[    2.838837] [<8018d010>] do_vfs_ioctl+0xa4/0x6e4
[    2.843420] [<8018d6b0>] SyS_ioctl+0x60/0xa0
[    2.847680] [<800293c8>] syscall_common+0x30/0x54
[    2.852353]
[    2.853906] ---[ end trace 02b9cbc0208a022b ]---
[    2.858486] ubi1 error: ubi_scan_fastmap: Attach by fastmap failed, 
doing a full scan!

After some analysis I've found that the fault is not a lost PEB as the 
comment above the warning seems to indicate but instead a duplicate 
entry. One of the PEBs is present both in the free list and the WL pool. 
The PEB is free so scan_pool() puts it in the free list again with the 
result that count_fastmap_pebs() returns a higher count than expected 
due to the now duplicated entry in the free list.

I've done some debugging of how the fastmap is written and have found 
the following chain of events causing the duplicate entry:
- ubi_update_fastmap() calls ubi_refill_pools() resulting in the pools 
having only unused PEBs.
- ubi_update_fastmap() continues to run without wl_lock while it 
allocates a PEB for the fastmap.
- wear_leveling_worker() wakes up and tries to move a PEB but fails. 
I've seen both "PEB x has no VID header" and ubi_eba_copy_leb() 
returning MOVE_RETRY, but both result in a goto to out_not_moved which 
will call do_sync_erase() that results in the PEB being added to the 
free list.
- ubi_write_fastmap() takes wl_lock and creates a fastmap which includes 
a pool with used entries and the used PEB also being in the free list.

That's how far I've followed this. I guess either the worker thread 
needs to stay away from the pools until ubi_update_fastmap() has 
completed or this error needs to checked for and handled either in 
ubi_write_fastmap() or ubi_scan_fastmap().

I do not know why I'm seeing this so often (happens roughly 1/5 to 1/10 
of every boot on my device) or why it only happens with one of the two 
UBI partitions, but it seems to always include the same PEB being 
duplicated. According to my debug prints, the wear leveling worker is 
very fond of trying and failing to move things to PEB 85 and thus 
erasing it again at every boot even though no data is ever written to it 
(except the EC header).


ubinfo for the partition which I'm seeing the problem on:

# ubinfo /dev/ubi1
ubi1
Volumes count:                           2
Logical eraseblock size:                 129024 bytes, 126.0 KiB
Total amount of logical eraseblocks:     160 (20643840 bytes, 19.7 MiB)
Amount of available logical eraseblocks: 48 (6193152 bytes, 5.9 MiB)
Maximum count of volumes                 128
Count of bad physical eraseblocks:       0
Count of reserved physical eraseblocks:  40
Current maximum erase counter value:     55
Minimum input/output unit size:          2048 bytes
Character device major/minor:            250:0
Present volumes:                         15, 24
# ubinfo /dev/ubi1_15
Volume ID:   15 (on ubi1)
Type:        dynamic
Alignment:   1
Size:        1 LEBs (129024 bytes, 126.0 KiB)
State:       OK
Name:        bootblockpar
Character device major/minor: 250:16
# ubinfo /dev/ubi1_24
Volume ID:   24 (on ubi1)
Type:        dynamic
Alignment:   1
Size:        65 LEBs (8386560 bytes, 8.0 MiB)
State:       OK
Name:        persistent
Character device major/minor: 250:25


I'm seeing this problem on multiple systems (all with same partition 
layout) running both 32bit MIPS and 32bit ARM, most of them with muliple 
cores but fault has also been seen at least once on a single core system.
Currently using Linux 4.4.19 but haven't seen any changes in 4.8-rc3 
that should make any difference for this problem.

/Anders

Re: UBI: Race between fastmap_write and wear_leveling_worker

[Richard Weinberger]

Anders,

On Wed, Aug 24, 2016 at 1:37 PM, Anders Olofsson <pingu@mazeda.se> wrote:
> After enabling fastmap I sometimes get the following warning at boot:
>
> [    2.612424] ubi1: default fastmap pool size: 8
> [    2.616802] ubi1: default fastmap WL pool size: 4
> [    2.621412] ubi1: attaching mtd3
> [    2.739113] ------------[ cut here ]------------
> [    2.743623] WARNING: CPU: 0 PID: 102 at drivers/mtd/ubi/fastmap.c:832
> ubi_scan_fastmap+0x145c/0x1464()
> [    2.752929] Modules linked in:
> [    2.755932] CPU: 0 PID: 102 Comm: ubiattach Not tainted 4.4.19 #24
> [    2.762077] Stack : 80916aaa 00000036 80910000 00000000 00000000 00000000
> 80095c08 8081fca7
>           8fef19d8 00000066 00000000 80904f60 8f49c400 8f592000 00000000
> 80095c38
>           00000000 803b0078 00000002 00000000 807659f8 8f5a7c14 8f5a7bfc
> 8012b6c0
>           00000009 80044808 8f49c400 8f592000 8f5a7c14 00000082 00000200
> 8075ccd8
>           00000000 00000000 00000000 00000000 00000000 00000000 00000000
> 00000000
>           ...
> [    2.797492] Call Trace:
> [    2.799939] [<80020894>] show_stack+0x94/0xb0
> [    2.804277] [<803a17d8>] dump_stack+0x88/0xc0
> [    2.808633] [<8004497c>] warn_slowpath_common+0xa4/0xe0
> [    2.813822] [<800449dc>] warn_slowpath_null+0x24/0x30
> [    2.818860] [<80454e98>] ubi_scan_fastmap+0x145c/0x1464
> [    2.824077] [<80451754>] ubi_attach+0x2e8/0x4b4
> [    2.828585] [<80441400>] ubi_attach_mtd_dev+0x9f4/0x10fc
> [    2.833872] [<80441e10>] ctrl_cdev_ioctl+0x100/0x204
> [    2.838837] [<8018d010>] do_vfs_ioctl+0xa4/0x6e4
> [    2.843420] [<8018d6b0>] SyS_ioctl+0x60/0xa0
> [    2.847680] [<800293c8>] syscall_common+0x30/0x54
> [    2.852353]
> [    2.853906] ---[ end trace 02b9cbc0208a022b ]---
> [    2.858486] ubi1 error: ubi_scan_fastmap: Attach by fastmap failed, doing
> a full scan!
>
> After some analysis I've found that the fault is not a lost PEB as the
> comment above the warning seems to indicate but instead a duplicate entry.
> One of the PEBs is present both in the free list and the WL pool. The PEB is
> free so scan_pool() puts it in the free list again with the result that
> count_fastmap_pebs() returns a higher count than expected due to the now
> duplicated entry in the free list.
>
> I've done some debugging of how the fastmap is written and have found the
> following chain of events causing the duplicate entry:
> - ubi_update_fastmap() calls ubi_refill_pools() resulting in the pools
> having only unused PEBs.
> - ubi_update_fastmap() continues to run without wl_lock while it allocates a
> PEB for the fastmap.
> - wear_leveling_worker() wakes up and tries to move a PEB but fails. I've
> seen both "PEB x has no VID header" and ubi_eba_copy_leb() returning
> MOVE_RETRY, but both result in a goto to out_not_moved which will call
> do_sync_erase() that results in the PEB being added to the free list.
> - ubi_write_fastmap() takes wl_lock and creates a fastmap which includes a
> pool with used entries and the used PEB also being in the free list.
>
> That's how far I've followed this. I guess either the worker thread needs to
> stay away from the pools until ubi_update_fastmap() has completed or this
> error needs to checked for and handled either in ubi_write_fastmap() or
> ubi_scan_fastmap().

Hehe, you're lucky I've recently fixed an issue in this area, can you
please try:
http://lists.infradead.org/pipermail/linux-mtd/2016-August/068919.html

I did these fixes on top of an rather old customer kernel and started
upstreaming
them.

-- 
Thanks,
//richard

Re: UBI: Race between fastmap_write and wear_leveling_worker

[Anders Olofsson]

On 2016-08-24 17:04, Richard Weinberger wrote:
> Anders,
>
> On Wed, Aug 24, 2016 at 1:37 PM, Anders Olofsson <pingu@mazeda.se> wrote:
>> After enabling fastmap I sometimes get the following warning at boot:
>>
>
> Hehe, you're lucky I've recently fixed an issue in this area, can you
> please try:
> http://lists.infradead.org/pipermail/linux-mtd/2016-August/068919.html
>
> I did these fixes on top of an rather old customer kernel and started
> upstreaming
> them.
>

Tested it and from what I can tell it solves my problem as well. I've 
run a bunch of reboots and the wear leveling worker no longer runs while 
the fastmap is being updated.

Good work and thanks a lot for solving it so quickly.

Re: UBI: Race between fastmap_write and wear_leveling_worker

[Richard Weinberger]

Anders,

On 25.08.2016 08:52, Anders Olofsson wrote:
> On 2016-08-24 17:04, Richard Weinberger wrote:
>> Anders,
>>
>> On Wed, Aug 24, 2016 at 1:37 PM, Anders Olofsson <pingu@mazeda.se> wrote:
>>> After enabling fastmap I sometimes get the following warning at boot:
>>>
>>
>> Hehe, you're lucky I've recently fixed an issue in this area, can you
>> please try:
>> http://lists.infradead.org/pipermail/linux-mtd/2016-August/068919.html
>>
>> I did these fixes on top of an rather old customer kernel and started
>> upstreaming
>> them.
>>
> 
> Tested it and from what I can tell it solves my problem as well. I've run a bunch of reboots and the wear leveling worker no longer runs while the fastmap is being updated.
> 
> Good work and thanks a lot for solving it so quickly.

How do you test? I wonder how you can trigger this so easily.
The said patch emerged while a customer did excessive Fastmap testing
and the race appeared only once. I found it while staring at the code.

But it is good to see that finally after years embedded Folks start
using Fastmap and non-obvious issues can get sorted out.

Thanks,
//richard

Re: UBI: Race between fastmap_write and wear_leveling_worker

[Anders Olofsson]

On 2016-08-25 09:38, Richard Weinberger wrote:
> On 25.08.2016 08:52, Anders Olofsson wrote:
>> On 2016-08-24 17:04, Richard Weinberger wrote:
>>> Anders,
>>>
>>> On Wed, Aug 24, 2016 at 1:37 PM, Anders Olofsson <pingu@mazeda.se> wrote:
>>>> After enabling fastmap I sometimes get the following warning at boot:
>>>>
>>>
>>> Hehe, you're lucky I've recently fixed an issue in this area, can you
>>> please try:
>>> http://lists.infradead.org/pipermail/linux-mtd/2016-August/068919.html
>>>
>>> I did these fixes on top of an rather old customer kernel and started
>>> upstreaming
>>> them.
>>>
>>
>> Tested it and from what I can tell it solves my problem as well. I've run a bunch of reboots and the wear leveling worker no longer runs while the fastmap is being updated.
>>
>> Good work and thanks a lot for solving it so quickly.
>
> How do you test? I wonder how you can trigger this so easily.
> The said patch emerged while a customer did excessive Fastmap testing
> and the race appeared only once. I found it while staring at the code.

I don't know what I'm doing that makes my system special. I can only 
guess it's related to the size of the UBI partition since it only 
happens on the smaller of the two partitions we use (160 PEBs vs. 1830 
in the larger partition where I've never seen this happen).
Having only 160 PEBs means the WL pool consists of only 4 PEBs if that 
could be any clue to the behaviors I'm describing here.

If size is the key, then the setup is a 20MB partition with a 8MB UBIFS 
volume in it and the only thing I need to do to trigger this is to 
attach the partition and mount the filesystem. I think my system may 
also do some small write to a file in the filesystem, but mostly just 
reading. Clean reboot or power cycle seems to work equally well in 
triggering the fault.

What I have seen is that at every boot, the wear leveling worker always 
wants to relocate one PEB and always fails. The source PEB varies but 
the target PEB is always the first one from the WL pool. The relocation 
always fails, either because the source block is unused or because it is 
locked and the handling in the worker is to always erase the destination 
PEB and this was happening while the fastmap was being updated.
This by itself sounds like a bug somewhere, there should be no need to 
erase the destination PEB when the wear leveling was aborted before 
anything was written. Since it is always the same PEB, the result is 
this PEB having a much higher erase count than the other PEBs in the 
partition.

The wear leveling always seems to happen right after attaching and the 
fastmap is also always rewritten at this time. From what I've understood 
so far from the fastmap logic, I don't see why it needs to update the 
map at every boot though, but it happens on my partition and since both 
of these happens at the same time the race occurs often enough to be 
visible as more than just a small glitch.
This behavior is of course the same with your patch. The only difference 
is that the wear leveling worker isn't allowed to run until after the 
fastmap update is completed.

I did notice the fault happening more easily while I was debugging, so 
having a lot of debug prints in the code made the race window larger, 
but I still got this at least 1/10 of every boot before adding any 
prints on the multi-core systems.


> But it is good to see that finally after years embedded Folks start
> using Fastmap and non-obvious issues can get sorted out.

I'm working on an embedded system where boot times are becoming more and 
more important. Using fastmap removes a whole second from our total boot 
time (half in boot loader and half in kernel) so this was definitely a 
good feature for us.

/Anders