firmware transaction timeout issue
Closed this issue · 3 comments
hello,
I have a raspistill job in crontab, running every 3 minutes to take a picture:
sudo killall raspistill; python3 /home/pi/program/skycamv3.py >/dev/null 2>&1
the python program only defines some raspistill parameters, such as output file name, text annotations and shutter time. Then it invokes raspistill via a shell command
Unfortunately, after several hours, it run in some issue: raspistill stop working.
If I run raspistill from command line, it works "forever", unless I go with ctrl+c.
No error messages from raspistill.
This is running on raspbian lite (no desktop), Raspberry Pi4 model B, 4GB RAM.
Any advise ?
Please find the log below.
Thanks
Frank
Apr 6 06:27:10 raspberrypi CRON[5365]: (CRON) info (No MTA installed, discarding output)
Apr 6 06:30:01 raspberrypi CRON[5388]: (pi) CMD (sudo killall raspistill; python3 /home/pi/program/skycamv3.py >/dev/null 2>&1)
Apr 6 06:30:09 raspberrypi CRON[5387]: (CRON) info (No MTA installed, discarding output)
Apr 6 06:31:50 raspberrypi rngd[349]: stats: bits received from HRNG source: 320064
Apr 6 06:31:50 raspberrypi rngd[349]: stats: bits sent to kernel pool: 273824
Apr 6 06:31:50 raspberrypi rngd[349]: stats: entropy added to kernel pool: 273824
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS 140-2 successes: 16
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS 140-2 failures: 0
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS 140-2(2001-10-10) Poker: 0
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS 140-2(2001-10-10) Runs: 0
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS 140-2(2001-10-10) Long run: 0
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Apr 6 06:31:50 raspberrypi rngd[349]: stats: HRNG source speed: (min=231.388; avg=480.014; max=568.860)Kibits/s
Apr 6 06:31:50 raspberrypi rngd[349]: stats: FIPS tests speed: (min=4.809; avg=11.723; max=31.319)Mibits/s
Apr 6 06:31:50 raspberrypi rngd[349]: stats: Lowest ready-buffers level: 2
Apr 6 06:31:50 raspberrypi rngd[349]: stats: Entropy starvations: 0
Apr 6 06:31:50 raspberrypi rngd[349]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
Apr 6 06:33:01 raspberrypi CRON[5413]: (pi) CMD (sudo killall raspistill; python3 /home/pi/program/skycamv3.py >/dev/null 2>&1)
Apr 6 06:33:10 raspberrypi CRON[5412]: (CRON) info (No MTA installed, discarding output)
Apr 6 06:36:01 raspberrypi CRON[5434]: (pi) CMD (sudo killall raspistill; python3 /home/pi/program/skycamv3.py >/dev/null 2>&1)
Apr 6 06:36:09 raspberrypi kernel: [32666.468514] ------------[ cut here ]------------
Apr 6 06:36:09 raspberrypi kernel: [32666.468555] WARNING: CPU: 3 PID: 5191 at drivers/firmware/raspberrypi.c:64 rpi_firmware_transaction+0xe c/0x128
Apr 6 06:36:09 raspberrypi kernel: [32666.468570] Firmware transaction timeout
Apr 6 06:36:09 raspberrypi kernel: [32666.468584] Modules linked in: cmac bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc b rcmfmac brcmutil sha256_generic v3d gpu_sched bcm2835_codec(C) cfg80211 vc4 cec raspberrypi_hwmon rfkill drm_kms_helper i2c_bcm2835 v4l2_mem2m em drm bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_c ommon drm_panel_orientation_quirks snd_soc_core videodev vc_sm_cma(C) snd_compress mc snd_bcm2835(C) snd_pcm_dmaengine snd_pcm snd_timer snd s yscopyarea sysfillrect sysimgblt fb_sys_fops rpivid_mem backlight uio_pdrv_genirq uio nvmem_rmem i2c_dev ip_tables x_tables ipv6
Apr 6 06:36:09 raspberrypi kernel: [32666.469411] CPU: 3 PID: 5191 Comm: kworker/3:1 Tainted: G C 5.10.17-v7l+ #1403
Apr 6 06:36:09 raspberrypi kernel: [32666.469421] Hardware name: BCM2711
Apr 6 06:36:09 raspberrypi kernel: [32666.469446] Workqueue: events get_values_poll [raspberrypi_hwmon]
Apr 6 06:36:09 raspberrypi kernel: [32666.469464] Backtrace:
Apr 6 06:36:09 raspberrypi kernel: [32666.469496] [] (dump_backtrace) from [] (show_stack+0x20/0x24)
Apr 6 06:36:09 raspberrypi kernel: [32666.469511] r7:ffffffff r6:00000000 r5:60000013 r4:c12e69fc
Apr 6 06:36:09 raspberrypi kernel: [32666.469531] [] (show_stack) from [] (dump_stack+0xcc/0xf8)
Apr 6 06:36:09 raspberrypi kernel: [32666.469549] [] (dump_stack) from [] (__warn+0xfc/0x114)
Apr 6 06:36:09 raspberrypi kernel: [32666.469565] r10:dec02008 r9:00000009 r8:c099d5b8 r7:00000040 r6:00000009 r5:c099d5b8
Apr 6 06:36:09 raspberrypi kernel: [32666.469575] r4:c0e9abc8 r3:c1205094
Apr 6 06:36:09 raspberrypi kernel: [32666.469593] [] (__warn) from [] (warn_slowpath_fmt+0xa4/0xd8)
Apr 6 06:36:09 raspberrypi kernel: [32666.469606] r7:00000040 r6:c0e9abc8 r5:c1205048 r4:c0e9abe8
Apr 6 06:36:09 raspberrypi kernel: [32666.469626] [] (warn_slowpath_fmt) from [] (rpi_firmware_transaction+0xec/0x128)
Apr 6 06:36:09 raspberrypi kernel: [32666.469640] r9:c1a544c0 r8:00000010 r7:00000000 r6:ffffff92 r5:c1a544c0 r4:c1205048
Apr 6 06:36:09 raspberrypi kernel: [32666.469658] [] (rpi_firmware_transaction) from [] (rpi_firmware_property_list+0xbc/ 0x170)
Apr 6 06:36:09 raspberrypi kernel: [32666.469671] r7:c1205048 r6:dec02000 r5:00001000 r4:dec0201c
Apr 6 06:36:09 raspberrypi kernel: [32666.469689] [] (rpi_firmware_property_list) from [] (rpi_firmware_property+0x70/0x1 18)
Apr 6 06:36:09 raspberrypi kernel: [32666.469702] r10:c37fff8c r9:00030046 r8:00000010 r7:c1a544c0 r6:c4229ed8 r5:00000004
Apr 6 06:36:09 raspberrypi kernel: [32666.469712] r4:c37fff80
Apr 6 06:36:09 raspberrypi kernel: [32666.469733] [] (rpi_firmware_property) from [] (get_values_poll+0x4c/0x150 [raspber rypi_hwmon])
Apr 6 06:36:09 raspberrypi kernel: [32666.469746] r10:00000000 r9:00000000 r8:000000c0 r7:eff51900 r6:eff4e640 r5:c1a8454c
Apr 6 06:36:09 raspberrypi kernel: [32666.469757] r4:c1205048 r3:00000004
Apr 6 06:36:09 raspberrypi kernel: [32666.469777] [] (get_values_poll [raspberrypi_hwmon]) from [] (process_one_work+0x25 0/0x5a0)
Apr 6 06:36:09 raspberrypi kernel: [32666.469787] r5:c4ce3a00 r4:c1a8454c
Apr 6 06:36:09 raspberrypi kernel: [32666.469805] [] (process_one_work) from [] (worker_thread+0x60/0x5c4)
Apr 6 06:36:09 raspberrypi kernel: [32666.469818] r10:eff4e640 r9:c1203d00 r8:eff4e658 r7:00000008 r6:eff4e640 r5:c4ce3a14
Apr 6 06:36:09 raspberrypi kernel: [32666.469828] r4:c4ce3a00
Apr 6 06:36:09 raspberrypi kernel: [32666.469845] [] (worker_thread) from [] (kthread+0x170/0x174)
Apr 6 06:36:09 raspberrypi kernel: [32666.469859] r10:c4cb3e74 r9:c4ce3a00 r8:c023df68 r7:c4228000 r6:00000000 r5:c37ff340
Apr 6 06:36:09 raspberrypi kernel: [32666.469868] r4:c4257240
Apr 6 06:36:09 raspberrypi kernel: [32666.469883] [] (kthread) from [] (ret_from_fork+0x14/0x28)
Apr 6 06:36:09 raspberrypi kernel: [32666.469894] Exception stack(0xc4229fb0 to 0xc4229ff8)
Apr 6 06:36:09 raspberrypi kernel: [32666.469906] 9fa0: 00000000 00000000 00000000 00000000
Apr 6 06:36:09 raspberrypi kernel: [32666.469920] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000Apr 6 06:36:09 raspberrypi kernel: [32666.469932] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000A
pr 6 06:36:09 raspberrypi kernel: [32666.469946] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c02458e0Apr 6 06:36:09 raspberrypi kernel: [32666.469956] r4:c37ff340Apr 6 06:36:09 raspberrypi kernel: [32666.469969] ---[ end trace 40751f1a0de02467 ]---
Apr 6 06:36:09 raspberrypi kernel: [32666.470019] hwmon hwmon1: Failed to get throttled (-110)
Apr 6 06:36:10 raspberrypi kernel: [32667.508542] cpu cpu0: dev_pm_opp_set_rate: failed to find current OPP for freq 4294967186 (-34)
Apr 6 06:36:11 raspberrypi kernel: [32668.548582] raspberrypi-clk soc:firmware:clocks: Failed to change fw-clk-arm frequency: -110Apr 6 06:36:14 raspberrypi kernel: [32671.668691] cpu cpu0: dev_pm_opp_set_rate: failed to find current OPP for freq 4294967186 (-34)
Apr 6 06:36:15 raspberrypi kernel: [32672.708732] raspberrypi-clk soc:firmware:clocks: Failed to change fw-clk-arm frequency: -110
Apr 6 06:38:30 raspberrypi kernel: [32807.273454] INFO: task kworker/3:1:5191 blocked for more than 122 seconds.
Apr 6 06:38:30 raspberrypi kernel: [32807.273476] Tainted: G WC 5.10.17-v7l+ #1403
Apr 6 06:38:30 raspberrypi kernel: [32807.273491] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 6 06:38:30 raspberrypi kernel: [32807.273508] task:kworker/3:1 state:D stack: 0 pid: 5191 ppid: 2 flags:0x00000000
Apr 6 06:38:30 raspberrypi kernel: [32807.273561] Workqueue: events get_values_poll [raspberrypi_hwmon]
Apr 6 06:38:30 raspberrypi kernel: [32807.273590] Backtrace:
Apr 6 06:38:30 raspberrypi kernel: [32807.273637] [] (__schedule) from [] (schedule+0x68/0xe4)
Apr 6 06:38:30 raspberrypi kernel: [32807.273661] r10:dec03008 r9:eff47540 r8:eff47540 r7:c1205048 r6:c4229d8c r5:c3e69f00Apr 6 06:38:30 raspberrypi kernel: [32807.273677] r4:ffffe000Apr 6 06:38:30 raspberrypi kernel: [32807.273703] [] (schedule) from [] (schedule_timeout+0x1d0/0x384)
Apr 6 06:38:30 raspberrypi kernel: [32807.273721] r5:c1203d00 r4:0036e418Apr 6 06:38:30 raspberrypi kernel: [32807.273748] [] (schedule_timeout) from [] (wait_for_completion_timeout+0xb8/0x144)
Apr 6 06:38:30 raspberrypi kernel: [32807.273769] r9:00000002 r8:ffffe000 r7:c197ae90 r6:c1205048 r5:00057e40 r4:
Sounds a bit like raspberrypi/firmware#1552
It may be fixed by latest rpi-update firmware.
thanks ! I have done it.
Let's check :)
Hi,
after few day non-stop, my 2 Raspberry Pi 4 with HQ Camera are not presenting any issue.
Sounds like that was the problem. The fix worked.
Thank you !
francesco