init-eMMC-flasher mmcqd allocation failures

[pabigot]

Using a script derived from init-eMMC-flasher-v3.sh to rsync from a loopback-mounted file system to a newly created ext4 file system on the eMMC I periodically (~ 5% of attempts) get the failures below.  This has been replicated with kernels 4.1.16-ti-rt-r44 and 4.4.9-ti-r25 (both from pre-build console images), and on multiple BeagleBone Black revision C devices.  The effect is that the resulting partition has nulls in some files where there should be data.

Note that this is writing to the eMMC, not to an SD card, and the script process is running as init.  (The source image is sometimes on an SD card, and sometimes on an NFS-mounted root partition.)

The behavior and context is very much like the following topic but the kernel is much more recent and the device is being fed by a 5VDC 10A supply so should not be due to voltage sags.

https://groups.google.com/d/topic/beagleboard/C__ixv3bBBI/discussion

Can anybody provide a clue as to why this might happen, and if something can be done to prevent it?

Thanks.

Peter

Captured diagnostics over serial console running 4.4.9-ti-r25:

-----------------------------

Copying: /tmp/mnt/root -> /dev/mmcblk1p1

[   33.839562] EXT4-fs (mmcblk1p1): mounted filesystem with ordered data mode. Opts: (null)

rsync: /tmp/mnt/root -> /tmp/rootfs/

[  142.267382] mmcqd/1: page allocation failure: order:2, mode:0x208c020

[  142.273958] CPU: 0 PID: 77 Comm: mmcqd/1 Not tainted 4.4.9-ti-r25 #1

[  142.280338] Hardware name: Generic AM33XX (Flattened Device Tree)

[  142.286494] [<c0015b61>] (unwind_backtrace) from [<c00123f5>] (show_stack+0x11/0x14)

[  142.294286] [<c00123f5>] (show_stack) from [<c03c9023>] (dump_stack+0x73/0x80)

[  142.301555] [<c03c9023>] (dump_stack) from [<c00f79d1>] (warn_alloc_failed+0xb5/0xf0)

[  142.309427] [<c00f79d1>] (warn_alloc_failed) from [<c00f9fed>] (__alloc_pages_nodemask+0x5ed/0x748)

[  142.318516] [<c00f9fed>] (__alloc_pages_nodemask) from [<c00fa2a9>] (alloc_kmem_pages+0x15/0x78)

[  142.327349] [<c00fa2a9>] (alloc_kmem_pages) from [<c010d64f>] (kmalloc_order+0x13/0x20)

[  142.335392] [<c010d64f>] (kmalloc_order) from [<c010d675>] (kmalloc_order_trace+0x19/0x94)

[  142.343699] [<c010d675>] (kmalloc_order_trace) from [<c041a9d3>] (edma_prep_slave_sg+0x7b/0x258)

[  142.352528] [<c041a9d3>] (edma_prep_slave_sg) from [<c05b6417>] (omap_hsmmc_request+0x333/0x3ec)

[  142.361359] [<c05b6417>] (omap_hsmmc_request) from [<c05a428b>] (mmc_start_request+0xcb/0x1b0)

[  142.370013] [<c05a428b>] (mmc_start_request) from [<c05a4f93>] (mmc_start_req+0x203/0x2d4)

[  142.378323] [<c05a4f93>] (mmc_start_req) from [<c05b09c9>] (mmc_blk_issue_rw_rq+0x99/0x7f8)

[  142.386715] [<c05b09c9>] (mmc_blk_issue_rw_rq) from [<c05b125f>] (mmc_blk_issue_rq+0x137/0x36c)

[  142.395455] [<c05b125f>] (mmc_blk_issue_rq) from [<c05b2723>] (mmc_queue_thread+0x9f/0x148)

[  142.403850] [<c05b2723>] (mmc_queue_thread) from [<c0048383>] (kthread+0xaf/0xc4)

[  142.411375] [<c0048383>] (kthread) from [<c000ed15>] (ret_from_fork+0x11/0x1c)

[  142.418678] Mem-Info:

[  142.420972] active_anon:6521 inactive_anon:0 isolated_anon:0

[  142.420972]  active_file:13169 inactive_file:90132 isolated_file:0

[  142.420972]  unevictable:0 dirty:4997 writeback:5105 unstable:0

[  142.420972]  slab_reclaimable:12884 slab_unreclaimable:1371

[  142.420972]  mapped:687 shmem:0 pagetables:102 bounce:0

[  142.420972]  free:1086 free_pcp:51 free_cma:0

[  142.454003] Normal free:4344kB min:2836kB low:3544kB high:4252kB active_anon:26084kB inactive_anon:0kB active_file:52676kB inactive_file:360528kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:522240kB managed:503900kB mlocked:0kB dirty:19988kB writeback:20420kB mapped:2748kB shmem:0kB slab_reclaimable:51536kB slab_unreclaimable:5484kB kernel_stack:584kB pagetables:408kB unstable:0kB bounce:0kB free_pcp:204kB local_pcp:204kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no

[  142.499136] lowmem_reserve[]: 0 0 0

[  142.502684] Normal: 86*4kB (UME) 497*8kB (UE) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB = 4320kB

[  142.515179] 103305 total pagecache pages

[  142.519139] 0 pages in swap cache

[  142.522480] Swap cache stats: add 0, delete 0, find 0/0

[  142.527738] Free swap  = 0kB

[  142.530641] Total swap = 0kB

[  142.533541] 130560 pages RAM

[  142.536429] 0 pages HighMem/MovableOnly

[  142.540299] 4585 pages reserved

[  142.543464] 6144 pages cma reserved

[  142.546989] edma 49000000.edma: edma_prep_slave_sg: Failed to allocate a descriptor

[  142.554696] omap_hsmmc 481d8000.mmc: prep_slave_sg() failed

[  142.560307] omap_hsmmc 481d8000.mmc: MMC start dma failure

[  142.711393] mmcblk1: unknown error -1 sending read/write command, card status 0x900

[  142.719459] blk_update_request: I/O error, dev mmcblk1, sector 1007160

[  142.726072] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16993 (offset 0 size 4096 starting block 125896)

[  142.739111] Buffer I/O error on device mmcblk1p1, logical block 125639

[  142.745755] blk_update_request: I/O error, dev mmcblk1, sector 1007168

[  142.752358] blk_update_request: I/O error, dev mmcblk1, sector 1007176

[  142.758955] blk_update_request: I/O error, dev mmcblk1, sector 1007184

[  142.765550] blk_update_request: I/O error, dev mmcblk1, sector 1007192

[  142.772145] blk_update_request: I/O error, dev mmcblk1, sector 1007200

[  142.778740] blk_update_request: I/O error, dev mmcblk1, sector 1007208

[  142.785334] blk_update_request: I/O error, dev mmcblk1, sector 1007216

[  142.791929] blk_update_request: I/O error, dev mmcblk1, sector 1007224

[  142.798502] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16991 (offset 0 size 32768 starting block 125904)

[  142.811629] Buffer I/O error on device mmcblk1p1, logical block 125640

[  142.818215] Buffer I/O error on device mmcblk1p1, logical block 125641

[  142.824790] Buffer I/O error on device mmcblk1p1, logical block 125642

[  142.831362] Buffer I/O error on device mmcblk1p1, logical block 125643

[  142.837934] Buffer I/O error on device mmcblk1p1, logical block 125644

[  142.844506] Buffer I/O error on device mmcblk1p1, logical block 125645

[  142.851077] Buffer I/O error on device mmcblk1p1, logical block 125646

[  142.857650] Buffer I/O error on device mmcblk1p1, logical block 125647

[  142.864254] blk_update_request: I/O error, dev mmcblk1, sector 1007232

[  142.870902] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16992 (offset 0 size 16384 starting block 125908)

[  142.884038] Buffer I/O error on device mmcblk1p1, logical block 125648

[  142.891137] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16994 (offset 0 size 81920 starting block 125928)

[  142.904526] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16995 (offset 0 size 40960 starting block 125938)

[  142.917813] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16996 (offset 0 size 28672 starting block 125945)

[  142.931049] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16997 (offset 0 size 20480 starting block 125950)

[  142.944969] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16998 (offset 0 size 184320 starting block 125995)

[  142.958590] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 16999 (offset 0 size 86016 starting block 126016)

[  142.972043] EXT4-fs warning (device mmcblk1p1): ext4_end_bio:329: I/O error -5 writing to inode 17000 (offset 0 size 86016 starting block 126037)

[William Hermans]

No idea what the problem might be, but I'd probably try dd instead.

--
For more options, visit http://beagleboard.org/discuss
---
You received this message because you are subscribed to the Google Groups "BeagleBoard" group.
To unsubscribe from this group and stop receiving emails from it, send an email to beagleboard...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/beagleboard/b96eb3b9-7db5-48e3-8a92-b6382ca1d0b8%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Peter Bigot]

Thanks; that's the approach I'm going with.

You received this message because you are subscribed to a topic in the Google Groups "BeagleBoard" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/beagleboard/5ZwTUQwGSx4/unsubscribe.
To unsubscribe from this group and all its topics, send an email to beagleboard...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/beagleboard/CALHSORpQkq_ORBFJrKN0WQvvEAsyYsZdCFzd22jfnUgiHuRCNQ%40mail.gmail.com.

[William Hermans]

For subject completeness . . . You could even use dd to stuff the bootloaders into the MBR, and then tar to extract over a rootfs. But, this is slightly more complex. Personally I tend to like the less complex options. dd also has the advantage of a 1:1 bit copy where tar . . . yeah not so sure about that.

To view this discussion on the web visit https://groups.google.com/d/msgid/beagleboard/CAPOJ94O_WpcxyUMojgPQdRfE3UgvPhr0Rw_oaXX78KEc%2Bg9orA%40mail.gmail.com.

[William Hermans]

Right. . . using tar would also require using fdisk, or other suitable partitioning tool.

[Peter Bigot]

My hypothesis is that the underlying cause is a true failure that's tickled by running rsync in the shell script init process that provisions the device.  The images I'm installing have a huge number of very small files, and naive interpretation of the kernel messages suggests it can't handle the allocation associated with a new file without releasing memory that it can't release at that point.  Either the failure isn't communicated back to rsync or rsync ignores it and just leaves the file contents nulled.  Detecting the failure after provisioning completes is difficult.

Since I'm currently using pre-built Debian file systems/kernels/packages I can't try to isolate and fix the true issue, so my hope is moving to an installation technique that avoids the write-many-small-files behavior fixes the issue until I have a chance to switch to Yocto and get better control over what the system does.  If the problem recurs, I do still have the option of doing a md5sum over the entire partition to see whether a given dd invocation was successful, something I couldn't do with tar or rsync.

Peter

To view this discussion on the web visit https://groups.google.com/d/msgid/beagleboard/CALHSORoNF7t_y3OJEcDtnSg1NDgUsszE3NunnzUudn71m0vjpQ%40mail.gmail.com.

[Matthijs van Duin]

I've also run into this once during an apt-get upgrade, leaving the system in a pretty hosed state. I managed to recover it but it required a lot of effort. Although evidently rare, this is clearly a very serious issue.

The direct cause is edma_prep_slave_sg() failing to allocate memory for the struct edma_desc. I don't know whether the kernel is genuinely out of memory or if it simply cannot free it up immediately (the allocation is done with GPF_ATOMIC), and whether this is because it is filled with a backlog of writes or whether a leak of some sort is going on.

Instead of deferring until memory is available, or even just proceeding without DMA, the omap_hsmmc driver immediately fails the request with an error, thus pretty much guaranteeing loss of data or even filesystem corruption. I personally think this is completely unacceptable behaviour of a block driver.

I've been meaning to persue this matter on the linux-mmc and/or linux-omap lists, but since it was a single isolated incident and I have lots of other stuff to do I haven't been able to find the time and motivation yet.

Matthijs

[William Hermans]

Instead of deferring until memory is available, or even just proceeding without DMA, the omap_hsmmc driver immediately fails the request with an error, thus pretty much guaranteeing loss of data or even filesystem corruption. I personally think this is completely unacceptable behaviour of a block driver.

I agree with you 100%. Completely irresponsible and unacceptable. Problem is . . . 'open source', or in this case where the term 'open sores' I think applies.

--

For more options, visit http://beagleboard.org/discuss
---
You received this message because you are subscribed to the Google Groups "BeagleBoard" group.

To unsubscribe from this group and stop receiving emails from it, send an email to beagleboard+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/beagleboard/c052b765-78da-4257-857c-09a6046fe395%40googlegroups.com.

[William Hermans]

No idea if either of you 'flash' many devices at once. But it would be good to be 100% sure where, and why this issue occurs.

I have not experienced this issue at all. But quite honestly I think I've flashed the eMMC of only 3 different boards a few times each. In each case, rsync work flawlessly, and the whole copy operation was done in well under 2 minutes.

The image I've used: BBB-blank-debian-8.5-console-armhf-2016-06-19-2gb.img.xz

Powered by USB even, but a good known solid USB 3.0 port. When I check the PMIC registers, it says it set to 1300mA. So I have to assume that helps.

I do not know what else to add for the procedure I use. I use . . .

william@eee-pc:~$ uname -r
3.2.0-4-686-pae

To dd the image above to sdcard. Then it's been just a simple matter of booting the given board with the sdcard inserted . ..

But anyway, I would not rule out power related issues in any case. It's not looking likely, but not impossible.

[pabigot]

This is very useful information; thank you.

At this time I dd the entire image at provisioning time, and run the upgradable application from a loop-mounted image, so no update path involves writing many small files.  However I intend to transition very soon to Yocto with package updates that are likely to make the problem visible again.  At that time I'll actually be able to control the kernel configuration and source better than under debian, so if the problem is still present I'll see if I can propose a fix.

Peter