search

Hexxeh / rpi-firmware

Firmware files for the Raspberry Pi
Other
775 stars 208 forks source link

firmware transaction timeout issue #263

Closed sferlix closed 3 years ago

sferlix commented 3 years ago

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:

popcornmix commented 3 years ago

Sounds a bit like https://github.com/raspberrypi/firmware/issues/1552 It may be fixed by latest rpi-update firmware.

sferlix commented 3 years ago

thanks ! I have done it. Let's check :)

sferlix commented 3 years ago

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