Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Firmware transaction timeout on Pi4B #4047

Open
hailfinger opened this issue Jan 4, 2021 · 21 comments
Open

Firmware transaction timeout on Pi4B #4047

hailfinger opened this issue Jan 4, 2021 · 21 comments

Comments

@hailfinger
Copy link
Contributor

hailfinger commented Jan 4, 2021

Describe the bug
"Firmware transaction timeout" message and gst-launch hang on a Pi 4B 4GB when running gst-launch-1.0 playbin uri=https://some.domain/720p25-h264-aac.m3u8

To reproduce
Boot Pi 4B with Raspberry Pi OS (without X server), then run
gst-launch-1.0 playbin uri=https://some.domain/720p25-h264-aac.m3u8
I can try to upload the m3u8 file and associated stream somewhere.
So far, this has been 100% reproducible.

Expected behaviour
No hang.

Actual behaviour
"Firmware transaction timeout" message and gst-launch hang on a Pi 4B 4GB when running
gst-launch-1.0 playbin uri=https://some.domain/720p25-h264-aac.m3u8

System
raspinfo hangs, pasting all output before the hang:

System Information
Raspberry Pi 4 Model B Rev 1.2
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"

Raspberry Pi reference 2020-08-20
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 9a3a10bf1019ebb2d59053564dc6b90068bad27d, stage4

Linux pi4-nak1 5.4.79-v7l+ #1373 SMP Mon Nov 23 13:27:40 GMT 2020 armv7l GNU/Linux
Revision : b03112
Serial : 100000004ad7632c
Model : Raspberry Pi 4 Model B Rev 1.2

Logs
If applicable, add the relevant output from dmesg or similar.

[   95.340807] fuse: init (API version 7.31)
[  711.440163] ------------[ cut here ]------------
[  711.440185] WARNING: CPU: 1 PID: 31 at drivers/firmware/raspberrypi.c:63 rpi_firmware_transaction+0xec/0x128
[  711.440190] Firmware transaction timeout
[  711.440193] Modules linked in: fuse cmac rfcomm bnep hci_uart btbcm bluetooth ecdh_generic ecc xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 af_key 8021q garp stp llc spidev brcmfmac brcmutil sha256_generic libsha256 cfg80211 v3d rfkill raspberrypi_hwmon gpu_sched i2c_mux_pinctrl i2c_mux bcm2835_codec(C) i2c_bcm2835 vc4 spi_bcm2835 v4l2_mem2mem bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) videobuf2_vmalloc cec videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common drm_kms_helper videodev drm snd_bcm2835(C) mc vc_sm_cma(C) drm_panel_orientation_quirks snd_soc_core snd_compress snd_pcm_dmaengine snd_pcm snd_timer rpivid_mem snd syscopyarea sysfillrect sysimgblt fb_sys_fops uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6
[  711.440326] CPU: 1 PID: 31 Comm: kworker/1:1 Tainted: G         C        5.4.79-v7l+ #1373
[  711.440329] Hardware name: BCM2711
[  711.440336] Workqueue: events dbs_work_handler
[  711.440340] Backtrace: 
[  711.440350] [<c020dfb0>] (dump_backtrace) from [<c020e334>] (show_stack+0x20/0x24)
[  711.440355]  r7:ffffffff r6:00000000 r5:60000013 r4:c129fab0
[  711.440363] [<c020e314>] (show_stack) from [<c0a76254>] (dump_stack+0xd8/0x11c)
[  711.440370] [<c0a7617c>] (dump_stack) from [<c0222028>] (__warn+0xe0/0x108)
[  711.440375]  r10:cfc04008 r9:00000009 r8:c08dd810 r7:0000003f r6:00000009 r5:c08dd810
[  711.440378]  r4:c0e3a554 r3:00000000
[  711.440384] [<c0221f48>] (__warn) from [<c0222424>] (warn_slowpath_fmt+0xa4/0xc0)
[  711.440389]  r7:0000003f r6:c0e3a554 r5:c1204fc8 r4:c0e3a574
[  711.440395] [<c0222384>] (warn_slowpath_fmt) from [<c08dd810>] (rpi_firmware_transaction+0xec/0x128)
[  711.440400]  r9:cee307c0 r8:00000018 r7:00000000 r6:ffffff92 r5:cee307c0 r4:c1204fc8
[  711.440407] [<c08dd724>] (rpi_firmware_transaction) from [<c08dd908>] (rpi_firmware_property_list+0xbc/0x170)
[  711.440411]  r7:c1204fc8 r6:cfc04000 r5:00001000 r4:cfc04024
[  711.440418] [<c08dd84c>] (rpi_firmware_property_list) from [<c08dda2c>] (rpi_firmware_property+0x70/0x118)
[  711.440423]  r10:ceccb8cc r9:00030002 r8:00000018 r7:cee307c0 r6:cee19d48 r5:0000000c
[  711.440426]  r4:ceccb8c0
[  711.440434] [<c08dd9bc>] (rpi_firmware_property) from [<c0733718>] (raspberrypi_clock_property+0x54/0x7c)
[  711.440439]  r10:00000000 r9:c9e57100 r8:00000001 r7:c1367c98 r6:59682f00 r5:cee19d70
[  711.440442]  r4:c1204fc8 r3:0000000c
[  711.440449] [<c07336c4>] (raspberrypi_clock_property) from [<c073378c>] (raspberrypi_fw_get_rate+0x4c/0x70)
[  711.440452]  r5:00000000 r4:c1204fc8
[  711.440460] [<c0733740>] (raspberrypi_fw_get_rate) from [<c072a19c>] (clk_recalc+0x44/0x84)
[  711.440463]  r4:cef52900
[  711.440470] [<c072a158>] (clk_recalc) from [<c072a48c>] (__clk_recalc_rates+0x30/0x94)
[  711.440474]  r5:00000000 r4:cef52900
[  711.440480] [<c072a45c>] (__clk_recalc_rates) from [<c072a55c>] (clk_core_get_rate+0x6c/0x70)
[  711.440485]  r7:c1367c98 r6:c1204fc8 r5:29b92700 r4:cef52900
[  711.440491] [<c072a4f0>] (clk_core_get_rate) from [<c072a584>] (clk_get_rate+0x24/0x28)
[  711.440495]  r5:29b92700 r4:c9e53800
[  711.440501] [<c072a560>] (clk_get_rate) from [<c08aa2ac>] (dev_pm_opp_set_rate+0x70/0x4b4)
[  711.440507] [<c08aa23c>] (dev_pm_opp_set_rate) from [<c08b4af8>] (set_target+0x3c/0x64)
[  711.440512]  r10:00000000 r9:00000000 r8:00000001 r7:c1367c98 r6:00000000 r5:000aae60
[  711.440515]  r4:c9e53c00
[  711.440521] [<c08b4abc>] (set_target) from [<c08aef18>] (__cpufreq_driver_target+0x1a8/0x51c)
[  711.440526]  r7:c1367c98 r6:00000000 r5:c1204fc8 r4:c9e53c00
[  711.440532] [<c08aed70>] (__cpufreq_driver_target) from [<c08b2b5c>] (od_dbs_update+0xc4/0x170)
[  711.440537]  r10:00000000 r9:c87af800 r8:c864fa80 r7:c87af680 r6:c87af800 r5:c87af680
[  711.440540]  r4:c9e53c00
[  711.440546] [<c08b2a98>] (od_dbs_update) from [<c08b3da8>] (dbs_work_handler+0x3c/0x64)
[  711.440551]  r9:00000040 r8:c128fb08 r7:c9e53c00 r6:c87af684 r5:00000000 r4:c87af6b8
[  711.440558] [<c08b3d6c>] (dbs_work_handler) from [<c023e884>] (process_one_work+0x250/0x570)
[  711.440563]  r9:00000040 r8:00000000 r7:dff1e600 r6:dff1b300 r5:ced68080 r4:c87af6b8
[  711.440569] [<c023e634>] (process_one_work) from [<c023ec04>] (worker_thread+0x60/0x5d0)
[  711.440574]  r10:dff1b300 r9:c1203d00 r8:dff1b318 r7:00000008 r6:dff1b300 r5:ced68094
[  711.440577]  r4:ced68080
[  711.440584] [<c023eba4>] (worker_thread) from [<c0245fd0>] (kthread+0x170/0x174)
[  711.440588]  r10:ced15e74 r9:c023eba4 r8:ced68080 r7:cee18000 r6:00000000 r5:ced63080
[  711.440592]  r4:cee1a040
[  711.440597] [<c0245e60>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28)
[  711.440601] Exception stack(0xcee19fb0 to 0xcee19ff8)
[  711.440606] 9fa0:                                     00000000 00000000 00000000 00000000
[  711.440610] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[  711.440614] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[  711.440619]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0245e60
[  711.440622]  r4:ced63080
[  711.440627] ---[ end trace 473967205885bfb5 ]---
[  711.440642] cpu cpu0: dev_pm_opp_set_rate: failed to find current OPP for freq 4294967186 (-34)
[  712.480177] raspberrypi-clk soc:firmware:clocks: Failed to change fw-clk-arm frequency: -110
[  714.560189] hwmon hwmon1: Failed to get throttled (-110)
[  715.600193] cpu cpu0: dev_pm_opp_set_rate: failed to find current OPP for freq 4294967186 (-34)
[  716.640198] raspberrypi-clk soc:firmware:clocks: Failed to change fw-clk-arm frequency: -110
[  724.301679] vc_sm_cma_import_dmabuf: imported vc_sm_cma_get_buffer failed -512
[  724.301686] bcm2835_mmal_vchiq: vchiq_mmal_submit_buffer: vc_sm_import_dmabuf_fd failed, ret -512
[  724.301693] bcm2835-codec bcm2835-codec: device_run: Failed submitting op buffer

Additional context
Attached devices:

  • HDMI monitor
  • Ethernet cable
  • No USB devices, I'm accessing the Pi via SSH.
@hailfinger
Copy link
Contributor Author

In case it is relevant, here are the active lines in /boot/config.txt

grep -v "^$\|^#" /boot/config.txt
disable_overscan=1
framebuffer_width=1280
framebuffer_height=720
hdmi_force_hotplug=1
hdmi_group=1
hdmi_mode=19
dtparam=i2c_vc=on
dtparam=spi=on
dtparam=audio=on
[pi4]
dtoverlay=vc4-fkms-v3d
max_framebuffers=2
[all]
start_x=1
gpu_mem=512
enable_uart=1

@hailfinger
Copy link
Contributor Author

Just in case anyone else is encountering the bug:
Do NOT try to reboot with the reboot command, it will hang and you will need a power cycle to get access again. Force a hard reboot by running

echo s | sudo tee /proc/sysrq-trigger
echo u | sudo tee /proc/sysrq-trigger
echo b | sudo tee /proc/sysrq-trigger

@nkichukov
Copy link

Perhaps related or similar to: #4033

@blackguard
Copy link

I am getting this same hang today after updating and reboot.

@popcornmix
Copy link
Collaborator

Possibly duplicate of this issue: raspberrypi/firmware#1516

@txenoo
Copy link
Contributor

txenoo commented Jan 12, 2021

I was having a similar issue decoding h264 with a quite similar backtrace, I was using raspberrypi-firmware (1.20210104-1) and kernel 5.4.83 but it was solved after updating to raspberrypi-firmware (1.20210108-1) released last Friday.

@lynema
Copy link

lynema commented Mar 21, 2021

Similar issue here... the triggering action is very different. It locks up the camera at seemingly random times. After a lock, the camera, which is attached to the camera port via ribbon cable, will not function until the next restart. Usually it will hang on reboot. Today, it did reboot cleanly after the lock and after the camera was manually unplugged.

This had been working well for about a year before the issue started surfacing.

Last value in strace before raspistill hangs indefinately is
futex(0xb6f1b3c4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, NULL, FUTEX_BITSET_MATCH_ANY

dmesg attached.
Pi4Dmesg.txt

This also appears to have been asked on superuser.com (https://superuser.com/questions/1597683/raspbian-failed-to-change-fw-clk-arm-frequency)

@noviceiii
Copy link

noviceiii commented Mar 31, 2021

Just to add. Similar issue here. It locks the camera at random times. Raspi Pi 4 Headless. Tested with two different camera models.

Mar 30 11:38:39 megacam kernel: [45756.100162] ------------[ cut here ]------------
Mar 30 11:38:39 megacam kernel: [45756.100199] WARNING: CPU: 3 PID: 5864 at drivers/firmware/raspberrypi.c:64 rpi_firmware_transaction+0xec/0x128
Mar 30 11:38:39 megacam kernel: [45756.100212] Firmware transaction timeout
Mar 30 11:38:39 megacam kernel: [45756.100224] Modules linked in: cmac bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc brcmfmac brcmutil vc4 ce
c drm_kms_helper sha256_generic v3d gpu_sched drm bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_isp(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) cfg80211 videobuf2_dma_conti
g videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common snd_soc_core rfkill drm_panel_orientation_quirks raspberrypi_hwmon snd_bcm2835(C) snd_compre
ss snd_pcm_dmaengine videodev snd_pcm snd_timer syscopyarea mc snd sysfillrect vc_sm_cma(C) sysimgblt fb_sys_fops backlight rpivid_mem uio_pdrv_genirq nvmem_rmem
 uio ip_tables x_tables ipv6
Mar 30 11:38:39 megacam kernel: [45756.100919] CPU: 3 PID: 5864 Comm: kworker/3:2 Tainted: G         C        5.10.23-v7l+ #1406
Mar 30 11:38:39 megacam kernel: [45756.100927] Hardware name: BCM2711
Mar 30 11:38:39 megacam kernel: [45756.100944] Workqueue: events dbs_work_handler
Mar 30 11:38:39 megacam kernel: [45756.100959] Backtrace: 
Mar 30 11:38:39 megacam kernel: [45756.100986] [<c0b729b0>] (dump_backtrace) from [<c0b72d44>] (show_stack+0x20/0x24)
Mar 30 11:38:39 megacam kernel: [45756.101000]  r7:ffffffff r6:00000000 r5:60000013 r4:c12e6a3c
Mar 30 11:38:39 megacam kernel: [45756.101017] [<c0b72d24>] (show_stack) from [<c0b770d4>] (dump_stack+0xcc/0xf8)
Mar 30 11:38:39 megacam kernel: [45756.101036] [<c0b77008>] (dump_stack) from [<c0220bac>] (__warn+0xfc/0x114)
Mar 30 11:38:39 megacam kernel: [45756.101050]  r10:dec02008 r9:00000009 r8:c09acb20 r7:00000040 r6:00000009 r5:c09acb20
Mar 30 11:38:39 megacam kernel: [45756.101059]  r4:c0e9f074 r3:c1205094
Mar 30 11:38:39 megacam kernel: [45756.101075] [<c0220ab0>] (__warn) from [<c0b734e8>] (warn_slowpath_fmt+0xa4/0xd8)
Mar 30 11:38:39 megacam kernel: [45756.101086]  r7:00000040 r6:c0e9f074 r5:c1205048 r4:c0e9f094
Mar 30 11:38:39 megacam kernel: [45756.101102] [<c0b73448>] (warn_slowpath_fmt) from [<c09acb20>] (rpi_firmware_transaction+0xec/0x128)
Mar 30 11:38:39 megacam kernel: [45756.101114]  r9:c1a542c0 r8:00000018 r7:00000000 r6:ffffff92 r5:c1a542c0 r4:c1205048
Mar 30 11:38:39 megacam kernel: [45756.101129] [<c09aca34>] (rpi_firmware_transaction) from [<c09acc18>] (rpi_firmware_property_list+0xbc/0x170)
Mar 30 11:38:39 megacam kernel: [45756.101140]  r7:c1205048 r6:dec02000 r5:00001000 r4:dec02024

@6by9
Copy link
Contributor

6by9 commented Mar 31, 2021

Quoting

Mar 30 11:38:39 megacam kernel: [45756.100199] WARNING: CPU: 3 PID: 5864 at drivers/firmware/raspberrypi.c:64 rpi_firmware_transaction+0xec/0x128
Mar 30 11:38:39 megacam kernel: [45756.100212] Firmware transaction timeout

is useless. It just means that a firmware transaction has failed to get a response. There is no further useful debug information in there. Please don't bother quoting the backtrace.

For a recent camera related issue see raspberrypi/firmware#1552 (now resolved and fix available via rpi-update)

The OP appears to be audio related. In which case again there has been an audio fix recently, and the kernel has bumped from 5.4 to 5.10. Please retest on the latest kernel.

@keks24
Copy link

keks24 commented Oct 21, 2021

I just encountered the same issue with my SanDisk Sansa Clip+ with Rockbox installed:

$ dmesg --follow
[...]
[92775.071098] usb 1-1.1: new high-speed USB device number 15 using xhci_hcd
[92785.041330] usb 1-1.1: new high-speed USB device number 16 using xhci_hcd
[92785.172497] usb 1-1.1: New USB device found, idVendor=0781, idProduct=74d1, bcdDevice= 1.00
[92785.172519] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[92785.172538] usb 1-1.1: Product: Rockbox media player
[92785.172555] usb 1-1.1: Manufacturer: Rockbox.org
[92785.172572] usb 1-1.1: SerialNumber: 2A8C3688501E9FF6100000000
[92785.189881] input: Rockbox.org Rockbox media player Keyboard as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1:1.0/0003:0781:74D1.0006/input/input10
[92785.252460] input: Rockbox.org Rockbox media player Consumer Control as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.1/1-1.1:1.0/0003:0781:74D1.0006/input/input11
[92785.252714] hid-generic 0003:0781:74D1.0006: input,hidraw0: USB HID v1.10 Keyboard [Rockbox.org Rockbox media player] on usb-0000:01:00.0-1.1/input0
[92809.840502] usb 1-1.1: USB disconnect, device number 16
[92824.472104] usb 1-1.1: new high-speed USB device number 17 using xhci_hcd
[92831.202229] ------------[ cut here ]------------
[92831.202265] WARNING: CPU: 3 PID: 26310 at drivers/firmware/raspberrypi.c:64 rpi_firmware_transaction+0xec/0x128
[92831.202280] Firmware transaction timeout
[92831.202294] Modules linked in: sg joydev cmac bnep hci_uart btbcm bluetooth ecdh_generic ecc brcmfmac brcmutil usblp sha256_generic vc4 cfg80211 cec rfkill drm_kms_helper v3d gpu_sched raspberrypi_hwmon bcm2835_isp(C) bcm2835_codec(C) v4l2_mem2mem bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) drm videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops snd_bcm2835(C) videobuf2_v4l2 videobuf2_common drm_panel_orientation_quirks snd_soc_core videodev vc_sm_cma(C) snd_compress snd_pcm_dmaengine mc snd_pcm rpivid_mem snd_timer snd syscopyarea sysfillrect sysimgblt fb_sys_fops backlight nvmem_rmem uio_pdrv_genirq uio g_ether usb_f_rndis u_ether libcomposite dwc2 roles ip_tables x_tables nhpoly1305 chacha_generic libchacha chacha_neon adiantum libpoly1305 algif_skcipher af_alg ipv6 dm_crypt dm_mod
[92831.203296] CPU: 3 PID: 26310 Comm: kworker/3:0 Tainted: G         C        5.10.63-v7l+ #1457
[92831.203306] Hardware name: BCM2711
[92831.203331] Workqueue: events get_values_poll [raspberrypi_hwmon]
[92831.203348] Backtrace:
[92831.203379] [<c0b835a4>] (dump_backtrace) from [<c0b83938>] (show_stack+0x20/0x24)
[92831.203394]  r7:ffffffff r6:00000000 r5:60000013 r4:c12e6b3c
[92831.203412] [<c0b83918>] (show_stack) from [<c0b87d24>] (dump_stack+0xcc/0xf8)
[92831.203432] [<c0b87c58>] (dump_stack) from [<c0220b10>] (__warn+0xfc/0x114)
[92831.203447]  r10:da404008 r9:00000009 r8:c09bceb4 r7:00000040 r6:00000009 r5:c09bceb4
[92831.203458]  r4:c0ea170c r3:c1205094
[92831.203474] [<c0220a14>] (__warn) from [<c0b840dc>] (warn_slowpath_fmt+0xa4/0xd8)
[92831.203486]  r7:00000040 r6:c0ea170c r5:c1205048 r4:c0ea172c
[92831.203503] [<c0b8403c>] (warn_slowpath_fmt) from [<c09bceb4>] (rpi_firmware_transaction+0xec/0x128)
[92831.203516]  r9:c1a772c0 r8:00000010 r7:00000000 r6:ffffff92 r5:c1a772c0 r4:c1205048
[92831.203532] [<c09bcdc8>] (rpi_firmware_transaction) from [<c09bcfac>] (rpi_firmware_property_list+0xbc/0x170)
[92831.203544]  r7:c1205048 r6:da404000 r5:00001000 r4:da40401c
[92831.203558] [<c09bcef0>] (rpi_firmware_property_list) from [<c09bd0d0>] (rpi_firmware_property+0x70/0x118)
[92831.203572]  r10:c66bac4c r9:00030046 r8:00000010 r7:c1a772c0 r6:c7e45ed8 r5:00000004
[92831.203582]  r4:c66bac40
[92831.203600] [<c09bd060>] (rpi_firmware_property) from [<bf2890c0>] (get_values_poll+0x4c/0x150 [raspberrypi_hwmon])
[92831.203614]  r10:00000000 r9:00000000 r8:000000c0 r7:eff31a00 r6:eff2e6c0 r5:c2f52b4c
[92831.203625]  r4:c1205048 r3:00000004
[92831.203646] [<bf289074>] (get_values_poll [raspberrypi_hwmon]) from [<c023db68>] (process_one_work+0x250/0x5a0)
[92831.203656]  r5:c32edf00 r4:c2f52b4c
[92831.203673] [<c023d918>] (process_one_work) from [<c023df18>] (worker_thread+0x60/0x5c4)
[92831.203687]  r10:eff2e6c0 r9:c1203d00 r8:eff2e6d8 r7:00000008 r6:eff2e6c0 r5:c32edf14
[92831.203696]  r4:c32edf00
[92831.203713] [<c023deb8>] (worker_thread) from [<c02459f8>] (kthread+0x170/0x174)
[92831.203726]  r10:c3dffe74 r9:c32edf00 r8:c023deb8 r7:c7e44000 r6:00000000 r5:c66bae40
[92831.203736]  r4:c3331b40
[92831.203752] [<c0245888>] (kthread) from [<c02000ec>] (ret_from_fork+0x14/0x28)
[92831.203763] Exception stack(0xc7e45fb0 to 0xc7e45ff8)
[92831.203775] 5fa0:                                     00000000 00000000 00000000 00000000
[92831.203788] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[92831.203800] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[92831.203814]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0245888
[92831.203824]  r4:c66bae40
[92831.203837] ---[ end trace 8c2a1b359e189a16 ]---
[92831.203872] hwmon hwmon1: Failed to get throttled (-110)
[92832.242279] cpu cpu0: dev_pm_opp_set_rate: failed to find current OPP for freq 4294967186 (-34)
[92833.282241] raspberrypi-clk soc:firmware:clocks: Failed to change fw-clk-arm frequency: -110
[92834.602333] xhci_hcd 0000:01:00.0: Abort failed to stop command ring: -110
[92834.634377] xhci_hcd 0000:01:00.0: Host halt failed, -110
[92834.634382] xhci_hcd 0000:01:00.0: xHCI host controller not responding, assume dead
[92834.634399] xhci_hcd 0000:01:00.0: HC died; cleaning up
[92834.634500] xhci_hcd 0000:01:00.0: Timeout while waiting for setup device command
[92834.634618] usb 1-1: USB disconnect, device number 2
[92835.582329] usb 1-1.1: device not accepting address 17, error -108
[92835.582683] usb 1-1-port1: couldn't allocate usb_device
[92835.582741] usb 1-1.4: USB disconnect, device number 4

Could this also be related to #4597?

@gralpli
Copy link

gralpli commented Nov 30, 2022

I’m having the same problem today. I was running vcgencmd measure_temp every 10 minutes and after a couple weeks without error I got a “Firmware transaction timeout”:

[4294980.397415] ------------[ cut here ]------------
[4294980.397431] Firmware transaction timeout
[4294980.397472] WARNING: CPU: 1 PID: 816402 at drivers/firmware/raspberrypi.c:67 rpi_firmware_property_list+0x1dc/0x238
[4294980.397498] Modules linked in: cmac algif_hash aes_arm64 aes_generic algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc libaes 8021q garp stp llc snd_soc_hdmi_codec ftdi_sio usbserial brcmfmac vc4 brcmutil cec raspberrypi_hwmon drm_kms_helper cfg80211 bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) snd_soc_core rpivid_hevc(C) rfkill snd_compress vc_sm_cma(C) v4l2_mem2mem videobuf2_dma_contig videobuf2_vmalloc v3d snd_bcm2835(C) snd_pcm_dmaengine videobuf2_memops snd_pcm gpu_sched videobuf2_v4l2 syscopyarea videobuf2_common snd_timer i2c_brcmstb videodev snd sysfillrect mc sysimgblt fb_sys_fops nvmem_rmem uio_pdrv_genirq uio drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
[4294980.397638] CPU: 1 PID: 816402 Comm: kworker/1:2 Tainted: G         C        5.15.61-v8+ #1579
[4294980.397645] Hardware name: Raspberry Pi 4 Model B Rev 1.2 (DT)
[4294980.397649] Workqueue: events get_values_poll [raspberrypi_hwmon]
[4294980.397662] pstate: 80000005 (Nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[4294980.397667] pc : rpi_firmware_property_list+0x1dc/0x238
[4294980.397673] lr : rpi_firmware_property_list+0x1dc/0x238
[4294980.397679] sp : ffffffc009d9bcc0
[4294980.397681] x29: ffffffc009d9bcc0 x28: ffffffd7de8b06c8 x27: 00000000ffffff92
[4294980.397690] x26: ffffffc00847e008 x25: ffffff8048a55380 x24: 0000000000001000
[4294980.397699] x23: 0000000000000010 x22: ffffffd7de29a128 x21: ffffff80409da380
[4294980.397707] x20: ffffffc00847e000 x19: ffffffd7de8b05e8 x18: 0000000000000000
[4294980.397715] x17: 0000000000000000 x16: 0000000000000000 x15: 000000559f0ebf50
[4294980.397723] x14: 0000000000000000 x13: 74756f656d697420 x12: ffffffd7de7c6638
[4294980.397731] x11: 0000000000000003 x10: ffffffd7de7ae5f8 x9 : ffffffd7dd4ee8f4
[4294980.397739] x8 : 0000000000017fe8 x7 : c0000000ffffefff x6 : 0000000000000001
[4294980.397746] x5 : ffffffa91d345000 x4 : 0000000000000000 x3 : 0000000000000001
[4294980.397754] x2 : 0000000000000000 x1 : 94a24298c5346b00 x0 : 0000000000000000
[4294980.397762] Call trace:
[4294980.397765]  rpi_firmware_property_list+0x1dc/0x238
[4294980.397771]  rpi_firmware_property+0x78/0x110
[4294980.397777]  get_values_poll+0x50/0x120 [raspberrypi_hwmon]
[4294980.397783]  process_one_work+0x1f8/0x4a0
[4294980.397790]  worker_thread+0x50/0x480
[4294980.397795]  kthread+0x140/0x158
[4294980.397799]  ret_from_fork+0x10/0x20
[4294980.397806] ---[ end trace 0f27ccad9c9af14a ]---

After this error, vcgencmd doesn’t work anymore (it just hangs) and dmesg contains numerous other errors like Failed to change fw-clk-arm frequency which I guess is because of this.

@popcornmix
Copy link
Collaborator

@gralpli probably best to create a new issue.
"Firmware transaction timeout" basically means something has killed the firmware, so it won't respond to any command.
The original issue was provoked by firmware video decode. Yours sounds different.

But it would be useful if you could provide some clues to what provoked the failure. e.g. if you spot a pattern or running a certain program leads to "firmware transaction timeout" we may be able to reproduce it.

@T0maas
Copy link

T0maas commented Aug 23, 2023

Any updates? I have the same problem with Firmware transaction timeout. I am running Xorg session and today I had a black screen, I tried to restart lightdm but without success (systemctl restart lightdm does absolutely nothing). I also tried to kill Xorg with kill -9 but it was still running. Then I saw Firmware transaction timeout in dmesg. I had to restart system using echo b > /proc/sysrq-trigger

@popcornmix
Copy link
Collaborator

As has been mentioned previously "Firmware transaction timeout" on its own gives little information. Something has killed the firmware, so any subsequent call to it will fail and timeout.

What were you doing prior? Were you playing video or using camera?
Finding a reproducable set of operations that provoke this would be useful.

@T0maas
Copy link

T0maas commented Aug 24, 2023

I have installed rpi in kiosk, with touchscreen and content is displayed in chromium, there are some css animations. There is also installed monitoring system which checks if screen works, it periodically checks xrandr output if there is correct resolution and rotation (screen is rotated to left, portrait orientation).

Kiosk runs 24h, but chromium is driven by crontab (start at 7:00, stop at 19:00).

Window manager: openbox
Display manager: lightdm

Can chromium also cause "Firmware transaction timeout"? Or frequent calling of xrandr can cause this problem?

@popcornmix
Copy link
Collaborator

popcornmix commented Aug 24, 2023

Chromium can cause that if it plays embedded videos - does it?
Output of sudo vclog -m, and complete output of dmesg may be useful after a failure.
xrandr is unlikely to, assuming you are using the default kms driver, as firmware is not involved in driving the display.

@T0maas
Copy link

T0maas commented Aug 25, 2023

It happened again, chromium was loaded, but with white screen instead of black.
Output of dmesg after failure is here: https://pastebin.com/eZsK4Hsb

@popcornmix
Copy link
Collaborator

Looks like you are using the (now deprecated) fkms driver, and are on kernel 5.10. Are you on Buster?

You should switch to a bullseye image (which has 6.1 kernel) as whatever issues you have may have been fixed.

@T0maas
Copy link

T0maas commented Aug 25, 2023

Yes that is true, dtoverlay=vc4-fkms-v3d, Raspbian GNU/Linux 10 (buster), Linux raspberrypi 5.10.52-v7l+

@T0maas
Copy link

T0maas commented Dec 14, 2023

It happened again, I had to restart system using echo "b" > /proc/sysrq-trigger. This error happens randomly once every 3 months, but now it has been on 4 places from september until now.
I cant upgrade image, we have many kiosks (50+) running with RPI4 (kernel 5.10) on various places around country and it would be difficult to upgrade images to newer version. Is there another solution not involving image upgrade? Something which I can do remotely over ssh.

What about some watchdog, can it automatically restart system when this error happens?

@popcornmix
Copy link
Collaborator

You could enable the watchdog service which will reboot on a kernel hang, but I don't think you are hitting this here.

A better check would be script that checks that firmware side is responsive.

Possibly something like:

#!bin/bash
while timeout -k 1 1 vcgencmd version > /dev/null; do echo -n .; done
reboot &
sleep 10
echo "b" > /proc/sysrq-trigger.

The while should run forever, but if firmware fails to respond, it will try rebooting and then forcing a reboot.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests