Oops with vchiq_prepare_bulk_data (tc358743 + OMX JPEG encoder)

[mdevaev]

Describe the bug
The latest version of 5.10 kernel crashing when using OMX JPEG encoding and TC358743 with 720p video source resolution.

To reproduce
Take TC358743 and ustreamer.

git clone https://github.com/pikvm/ustreamer
cd ustreamer
make WITH_OMX=1

Add cma=128M to cmdline.txt and gpu_mem=256 to config.txt and try this command:

ustreamer --encoder=omx --dv-timings --persistent -m uyvy

You will see the crash.

System

• Raspberry Pi 4 B+ 4G
• Arch Linux ARM / PiKVM OS
• vcgencmd version:

  Nov  2 2021 13:22:15
  Copyright (c) 2012 Broadcom
  version e50fe24ee2b6974f3ba6615ba0f1d8f45c485f69 (clean) (release) (start)
  

• Linux pikvm 5.10.76-4-raspberrypi4-ARCH #1 SMP Fri Nov 5 08:11:58 MSK 2021 armv7l GNU/Linux

Logs
OOPS 1

[  853.623484] ------------[ cut here ]------------
[  853.628118] kernel BUG at kernel/dma/mapping.c:208!
[  853.633006] Internal error: Oops - BUG: 0 [#1] SMP ARM
Entering kdb (current=0xc3823c00, pid 1113) on processor 0 Oops: (null)
due to oops @ 0xc02a4f2c
CPU: 0 PID: 1113 Comm: ILCS_HOST Tainted: G         C        5.10.76-4-raspberrypi4-ARCH #1
Hardware name: BCM2711
PC is at dma_unmap_sg_attrs+0x40/0x44
LR is at 0x0
pc : [<c02a4f2c>]    lr : [<00000000>]    psr: 20080013
sp : c48c9d64  ip : 00000080  fp : 00000000
r10: 000000fc  r9 : 00000000  r8 : 00000000
r7 : 00000000  r6 : 00000006  r5 : c1a530f4  r4 : f0e2d0c8
r3 : 10801080  r2 : 10801080  r1 : 10801080  r0 : c1e69a10
Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 30c5383d  Table: 04139c00  DAC: fffffffd
CPU: 0 PID: 1113 Comm: ILCS_HOST Tainted: G         C        5.10.76-4-raspberrypi4-ARCH #1
Hardware name: BCM2711
[<c020f0d8>] (unwind_backtrace) from [<c020ae58>] (show_stack+0x10/0x14)
[<c020ae58>] (show_stack) from [<c0e08748>] (dump_stack+0xa4/0xc4)
[<c0e08748>] (dump_stack) from [<c0301eec>] (kdb_main_loop+0x4bc/0x9a0)
[<c0301eec>] (kdb_main_loop) from [<c0304fa0>] (kdb_stub+0x258/0x458)
[<c0304fa0>] (kdb_stub) from [<c02f9ff4>] (kgdb_cpu_enter+0x3e0/0x6fc)
more> ^M[<c02f9ff4>] (kgdb_cpu_enter) from [<c02fa9b4>] (kgdb_handle_exception+0xe0/0x13c)
more> ^M[<c02fa9b4>] (kgdb_handle_exception) from [<c020e794>] (kgdb_notify+0x28/0x48)
more> ^M[<c020e794>] (kgdb_notify) from [<c02503bc>] (notify_die+0x90/0xd0)
more> ^M[<c02503bc>] (notify_die) from [<c020af8c>] (die+0x130/0x34c)
more> ^M[<c020af8c>] (die) from [<c0200b94>] (__und_svc_finish+0x0/0x2c)
more> ^MException stack(0xc48c9cd0 to 0xc48c9d18)
more> ^M9cc0:                                     c1e69a10 10801080 10801080 10801080
more> ^M9ce0: f0e2d0c8 c1a530f4 00000006 00000000 00000000 00000000 000000fc 00000000
more> ^M9d00: 00000080 c48c9d64 00000000 c02a4f2c 20080013 ffffffff
more> ^M[<c0200b94>] (__und_svc_finish) from [<c02a4f2c>] (dma_unmap_sg_attrs+0x40/0x44)
more> ^M[<c02a4f2c>] (dma_unmap_sg_attrs) from [<c0c6509c>] (cleanup_pagelistinfo+0x98/0xb4)
more> ^M[<c0c6509c>] (cleanup_pagelistinfo) from [<c0c656c0>] (vchiq_prepare_bulk_data+0x190/0x6dc)
more> ^M[<c0c656c0>] (vchiq_prepare_bulk_data) from [<c0c5f0e4>] (vchiq_bulk_transfer+0x258/0x3e4)
more> ^M[<c0c5f0e4>] (vchiq_bulk_transfer) from [<c0c63530>] (vchiq_ioctl+0x724/0x17fc)
more> ^M[<c0c63530>] (vchiq_ioctl) from [<c044b198>] (sys_ioctl+0x34c/0x904)
more> ^M[<c044b198>] (sys_ioctl) from [<c0200040>] (ret_fast_syscall+0x0/0x4c)
more> ^MException stack(0xc48c9fa8 to 0xc48c9ff0)
more> ^M9fa0:                   b6b4b538 afefab1c 00000009 c014c406 afefab1c 000b900e
more> ^M9fc0: b6b4b538 afefab1c ac4ba020 00000036 00000000 3f155c40 ae504ce0 00000000
more> ^M9fe0: b6b4b240 afefab0c b6b38f44 b6c609fc
more> ^M
more> ^M[0]kdb>

OOPS 2

[  145.337313] ------------[ cut here ]------------
[  145.341993] kernel BUG at include/linux/scatterlist.h:95!
[  145.347427] Internal error: Oops - BUG: 0 [#1] SMP ARM
Entering kdb (current=0xc3c1da00, pid 755) on processor 0 Oops: (null)
due to oops @ 0xc0c65774
CPU: 0 PID: 755 Comm: ILCS_HOST Tainted: G         C        5.10.76-4-raspberrypi4-ARCH #1
Hardware name: BCM2711
PC is at vchiq_prepare_bulk_data+0x244/0x6dc
LR is at 0x0
pc : [<c0c65774>]    lr : [<00000000>]    psr: 00080013
sp : c4699d90  ip : 00000001  fp : c1934378
r10: 000006dc  r9 : 00000003  r8 : 00033700
r7 : f0e570e0  r6 : 00000035  r5 : f0e571b0  r4 : 00000035
r3 : 00001000  r2 : f0e571c8  r1 : 00000000  r0 : 3b713b9f
Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 30c5383d  Table: 03bb43c0  DAC: fffffffd
CPU: 0 PID: 755 Comm: ILCS_HOST Tainted: G         C        5.10.76-4-raspberrypi4-ARCH #1
Hardware name: BCM2711
[<c020f0d8>] (unwind_backtrace) from [<c020ae58>] (show_stack+0x10/0x14)
[<c020ae58>] (show_stack) from [<c0e08748>] (dump_stack+0xa4/0xc4)
[<c0e08748>] (dump_stack) from [<c0301eec>] (kdb_main_loop+0x4bc/0x9a0)
[<c0301eec>] (kdb_main_loop) from [<c0304fa0>] (kdb_stub+0x258/0x458)
[<c0304fa0>] (kdb_stub) from [<c02f9ff4>] (kgdb_cpu_enter+0x3e0/0x6fc)
more> ^M[<c02f9ff4>] (kgdb_cpu_enter) from [<c02fa9b4>] (kgdb_handle_exception+0xe0/0x13c)
more> ^M[<c02fa9b4>] (kgdb_handle_exception) from [<c020e794>] (kgdb_notify+0x28/0x48)
more> ^M[<c020e794>] (kgdb_notify) from [<c02503bc>] (notify_die+0x90/0xd0)
more> ^M[<c02503bc>] (notify_die) from [<c020af8c>] (die+0x130/0x34c)
more> ^M[<c020af8c>] (die) from [<c0200b94>] (__und_svc_finish+0x0/0x2c)
more> ^MException stack(0xc4699d00 to 0xc4699d48)
more> ^M9d00: 3b713b9f 00000000 f0e571c8 00001000 00000035 f0e571b0 00000035 f0e570e0
more> ^M9d20: 00033700 00000003 000006dc c1934378 00000001 c4699d90 00000000 c0c65774
more> ^M9d40: 00080013 ffffffff
more> ^M[<c0200b94>] (__und_svc_finish) from [<c0c65774>] (vchiq_prepare_bulk_data+0x244/0x6dc)
more> ^M[<c0c65774>] (vchiq_prepare_bulk_data) from [<c0c5f0e4>] (vchiq_bulk_transfer+0x258/0x3e4)
more> ^M[<c0c5f0e4>] (vchiq_bulk_transfer) from [<c0c63530>] (vchiq_ioctl+0x724/0x17fc)
more> ^M[<c0c63530>] (vchiq_ioctl) from [<c044b198>] (sys_ioctl+0x34c/0x904)
more> ^M[<c044b198>] (sys_ioctl) from [<c0200040>] (ret_fast_syscall+0x0/0x4c)
more> ^MException stack(0xc4699fa8 to 0xc4699ff0)
more> ^M9fa0:                   b6b4c538 afefab1c 00000009 c014c406 afefab1c 0002a00e
more> ^M9fc0: b6b4c538 afefab1c ad2ff020 00000036 00000000 3f155be0 ae504c70 00000000
more> ^M9fe0: b6b4c240 afefab0c b6b39f44 b6c619fc
more> ^M
more> ^M[0]kdb>

[mdevaev]

I have updated the description and localized the problem. It occurs when we try to use OMX JPEG encoding when capturing video from TC358743.

[pelwell]

The crash logs suggest the failures are the consequences of memory corruption.

[mdevaev]

It doesn't show up on 5.10.52, maybe it's some new bug? On the new kernel, failure occurs 100% of the time when using OMX.

[6by9]

Tripped when encoding JPEG with ustreamer
vcdbg log assert shows:

2485196.711: assert( vchiq: invalid pagelist at dad47000 - length 10801080, type 1080 (bulk TX) ) failed; ../../../../../interface/vchiq_arm/vchiq_2835_vc.c::vchiq_transfer_bulk line 152 rev e50fe24
vcdbg_ctx_get_dump_stack: dump_stack failed

Kernel oops

[ 6769.026131] 8<--- cut here ---
[ 6769.030113] Unable to handle kernel paging request at virtual address 10801080
[ 6769.031060] pgd = 838bd1c0
[ 6769.031891] [10801080] *pgd=80000000004003, *pmd=00000000
[ 6769.032725] Internal error: Oops: 206 [#1] SMP ARM
[ 6769.033538] Modules linked in: cmac bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc tc358743 snd_soc_hdmi_codec raspberrypi_hwmon brcmfmac brcmutil cfg80211 vc4 rfkill cec drm_kms_helper v3d gpu_sched bcm2835_v4l2(C) bcm2835_codec(C) drm videobuf2_vmalloc bcm2835_unicam i2c_brcmstb i2c_mux_pinctrl i2c_mux dwc2 v4l2_dv_timings roles v4l2_fwnode bcm2835_isp(C) bcm2835_mmal_vchiq(C) rpivid_hevc(C) v4l2_mem2mem videobuf2_dma_contig drm_panel_orientation_quirks videobuf2_memops videobuf2_v4l2 vc_sm_cma(C) videobuf2_common snd_soc_core snd_compress i2c_bcm2835 snd_pcm_dmaengine snd_pcm snd_timer videodev snd syscopyarea sysfillrect sysimgblt fb_sys_fops backlight mc uio_pdrv_genirq uio nvmem_rmem i2c_dev ip_tables x_tables ipv6
[ 6769.037938] CPU: 3 PID: 80 Comm: vchiq-slot/0 Tainted: G         C        5.10.76-v7l+ #1477
[ 6769.038808] Hardware name: BCM2711
[ 6769.039685] PC is at swiotlb_bounce+0x58/0x1f8
[ 6769.040564] LR is at 0xa6b20
[ 6769.041458] pc : [<c02a55f8>]    lr : [<000a6b20>]    psr: 60000013
[ 6769.042352] sp : c1af9d40  ip : 00000024  fp : c1af9d84
[ 6769.043236] r10: 00000000  r9 : c8aa6b20  r8 : d4890000
[ 6769.044138] r7 : 00000fe0  r6 : a6b20020  r5 : ffffffff  r4 : 00000c8a
[ 6769.045038] r3 : 37f71080  r2 : d8890000  r1 : c13d3880  r0 : a6b20020
[ 6769.045942] Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
[ 6769.046851] Control: 30c5383d  Table: 0384fdc0  DAC: 55555555
[ 6769.047768] Process vchiq-slot/0 (pid: 80, stack limit = 0xdc64cf67)
[ 6769.048708] Stack: (0xc1af9d40 to 0xc1afa000)
[ 6769.049639] 9d40: c1aa2e10 14890000 00000fe0 c13d3880 c120aed4 00000000 c1af9d94 00000c8a
[ 6769.050590] 9d60: ffffffff a6b20020 00000c8a 14890000 00000000 00000000 c1af9dac c1af9d88
[ 6769.051556] 9d80: c02a6258 c02a55ac 00000fe0 00000002 dad47100 c1aa2e10 14890000 00000000
[ 6769.052522] 9da0: c1af9e34 c1af9db0 c02a36fc c02a617c 00000fe0 00000002 00000000 c1af9dc8
[ 6769.053504] 9dc0: 14890000 00000000 00000002 c137c750 00000000 00000004 14890000 00000000
[ 6769.054481] 9de0: 14890000 00000000 00000000 0000001f c137c740 fffff000 00000fe0 00000000
[ 6769.055476] 9e00: 14890000 00000000 80000013 dad473e8 ffffffff 00000000 c1426960 c58b9000
[ 6769.056457] 9e20: 0000001f dad47000 c1af9e54 c1af9e38 c02a1bf0 c02a34cc 00000000 c0b9587c
[ 6769.057442] 9e40: c58b9050 dad473e8 c1af9eac c1af9e58 c09edbd0 c02a1b98 00000000 c0270aa0
[ 6769.058409] 9e60: c58b9000 c0b90214 00000000 00000008 c1af9e94 c1af9e80 c0b90214 dad47084
[ 6769.059385] 9e80: c58b91a0 c58b90e8 00000008 dad18978 c58b9100 c58b9000 c140641c dad00194
[ 6769.060368] 9ea0: c1af9f74 c1af9eb0 c09e8334 c09edb38 c020bbb4 c020ca78 c1205048 00000000
[ 6769.061359] 9ec0: c1a51480 c02446e8 c09e7350 c140641c c1af9f14 c0ea8f14 c0ea8f38 c0ea8f60
[ 6769.062356] 9ee0: c0ea8e20 c0ea9370 c0ea939c c0e55548 c1406514 c0ea8404 c58b91a0 c140643c
[ 6769.063352] 9f00: c14064ac c1406470 dad00194 c0c6c73c c142675c dad00020 c0ea7ff0 006059b8
[ 6769.064348] 9f20: 0000000e 00000057 c1320e58 00000010 00000000 c22fae80 c0270254 c1af9f3c
[ 6769.065348] 9f40: c1af9f3c c08c6bac c1af9f74 c1a51480 c2315700 00000000 c1af8000 c09e7350
[ 6769.066335] 9f60: c140641c c190dc1c c1af9fac c1af9f78 c0245b8c c09e735c c1a514a4 c1a514a4
[ 6769.067330] 9f80: ffffe000 c2315700 c0245a1c 00000000 00000000 00000000 00000000 00000000
[ 6769.068320] 9fa0: 00000000 c1af9fb0 c02000ec c0245a28 00000000 00000000 00000000 00000000
[ 6769.069305] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[ 6769.070293] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
[ 6769.071260] Backtrace: 
[ 6769.072243] [<c02a55a0>] (swiotlb_bounce) from [<c02a6258>] (swiotlb_tbl_sync_single+0xe8/0x114)
[ 6769.073254]  r10:00000000 r9:00000000 r8:14890000 r7:00000c8a r6:a6b20020 r5:ffffffff
[ 6769.074260]  r4:00000c8a
[ 6769.075265] [<c02a6170>] (swiotlb_tbl_sync_single) from [<c02a36fc>] (dma_direct_unmap_sg+0x23c/0x344)
[ 6769.076291]  r7:00000000 r6:14890000 r5:c1aa2e10 r4:dad47100
[ 6769.077317] [<c02a34c0>] (dma_direct_unmap_sg) from [<c02a1bf0>] (dma_unmap_sg_attrs+0x64/0x70)
[ 6769.078369]  r10:dad47000 r9:0000001f r8:c58b9000 r7:c1426960 r6:00000000 r5:ffffffff
[ 6769.079414]  r4:dad473e8
[ 6769.080450] [<c02a1b8c>] (dma_unmap_sg_attrs) from [<c09edbd0>] (vchiq_complete_bulk+0xa4/0x304)
[ 6769.081490]  r4:dad473e8
[ 6769.082496] [<c09edb2c>] (vchiq_complete_bulk) from [<c09e8334>] (slot_handler_func+0xfe4/0x1710)
[ 6769.083521]  r10:dad00194 r9:c140641c r8:c58b9000 r7:c58b9100 r6:dad18978 r5:00000008
[ 6769.084505]  r4:c58b90e8
[ 6769.085459] [<c09e7350>] (slot_handler_func) from [<c0245b8c>] (kthread+0x170/0x174)
[ 6769.086412]  r10:c190dc1c r9:c140641c r8:c09e7350 r7:c1af8000 r6:00000000 r5:c2315700
[ 6769.087369]  r4:c1a51480
[ 6769.088322] [<c0245a1c>] (kthread) from [<c02000ec>] (ret_from_fork+0x14/0x28)
[ 6769.089308] Exception stack(0xc1af9fb0 to 0xc1af9ff8)
[ 6769.090281] 9fa0:                                     00000000 00000000 00000000 00000000
[ 6769.091274] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[ 6769.092266] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[ 6769.093248]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0245a1c
[ 6769.094239]  r4:c2315700
[ 6769.095211] Code: e003039c e5912000 e50b1038 e59b7004 (e7923003) 
[ 6769.096232] ---[ end trace 99e68b5b56a11422 ]---

Edit: Firmware looks to have died, but hasn't flushed the cache so vcdbg log msg tail end is corrupted.

[pelwell]

[ 6769.030113] Unable to handle kernel paging request at virtual address 10801080

Yep - that looks like (black) pixel data in a place where no pixel data should be.

[6by9]

Rebuilt my kernel at 2a29770 (5.10.77) and top of tree firmware (with a few local mods). Crashed.

Reset my firmware back ("17 and 10 different commits each, respectively", top commit from origin is bcdfe55d5). I'll bisect it.

[6by9]

Working at 1920x1080 seems to trigger things more frequently. (I was using 1280x720 before).

I've just had a

[   29.183297] bcm2835-dma fe007b00.dma: swiotlb buffer is full (sz: -1249856128 bytes), total 32768 (slots), used 6 (slots)

logged as well, which has also killed everything.

What I thought was working with 5.10.77 and my old firmware does fail at 1080p.

I'm reverting back to the firmware from 5.10.52, but one thought I do have is that the buffers allocated by bcm2835-unicam and consumed by the H264 encoder do NOT have to be aligned to a multiple of 16 lines, whilst the IL JPEG DOES need 16 line alignment. It's not that you're asking it to copy more data than is allocated?

Firmware from 5.10.52 has just crashed with the kernel logging swiotlb buffer is full again.

[pelwell]

sz: -1249856128 is more evidence of corruption (0xb580b580), as I suspect is any mention of swiotlb.

[6by9]

raspberrypi/rpi-firmware@c59a637 seems to be the first to really trip this, so it would imply something changed with #4641. Slightly odd as that didn't touch memory allocation of buffer usage, but there you go.

[mdevaev]

@6by9 I have already encountered alignment problems and spied code in yavta and gstreamer. At least it worked before the update.

• MMAL H264: https://github.com/pikvm/ustreamer/blob/master/src/ustreamer/h264/encoder.c#L159
• OMX JPEG: https://github.com/pikvm/ustreamer/blob/master/src/ustreamer/encoders/omx/encoder.c#L263
• Device stride: https://github.com/pikvm/ustreamer/blob/master/src/ustreamer/device.c#L527

[mdevaev]

Please let me know if I can help with testing or anything else.

[mdevaev]

By the way, how would you like the new V4L2 M2M interface to support JPEG encoding? Since you're throwing away proprietary libraries, it would be great to have a replacement for this feature. My idea was to make /dev/video21 for ril.image_encode. I will be happy to make draft implementation and patch if you are interested in taking this upstream.

I saw that libcamera uses libjpeg to encode images and on the RPi forum I was offered to use encoding on cores, but as you saw, 1080p encoding consumes a huge amount of CPU resources and takes more time, which is a disaster for PiKVM, we really need hardware encoding to keep zero latency.

PS: I'm sorry to ask this here. It's just that if M2M works and is accepted into the RPi upstream, I can forget about the problems of OMX :) Unless the crash described is related to something lower-level and will still require a fix.