search

raspberrypi / firmware

This repository contains pre-compiled binaries of the current Raspberry Pi kernel and modules, userspace libraries, and bootloader/GPU firmware.
5.15k stars 1.68k forks source link

Kernel error with QT EGLFS #1251

Open MateEke opened 5 years ago

MateEke commented 5 years ago

Describe the bug I have a PyQT5 "digital picture frame" program running on RPi Zero W. I have used it for almost two years with Raspbian Jessie, but now I have updated the system to Raspbian Buster and compiled QT 5.12.4 and PyQT 5.13. The program works fine for several hours, but after that a kernel error appears in the log and the GUI freezes. Every "background tasks" (bluetooth, mqtt, etc.) countinous to work fine.

My system info won't be too helpful, because I have run rpi-update (still don't know if it helps). Before that everything was "stock" I only used apt upgrade.

System https://pastebin.com/TSpf3wTp

Logs

Sep 12 02:19:54 frida kernel: [13760.542644] INFO: task kworker/0:0:1646 blocked for more than 120 seconds.
Sep 12 02:19:54 frida kernel: [13760.542717]       Tainted: G         C        4.19.66+ #1253
Sep 12 02:19:54 frida kernel: [13760.542725] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 12 02:19:54 frida kernel: [13760.542734] kworker/0:0     D    0  1646      2 0x00000000
Sep 12 02:19:54 frida kernel: [13760.542788] Workqueue: events dbs_work_handler
Sep 12 02:19:54 frida kernel: [13760.542846] [<c06d0648>] (__schedule) from [<c06d0b24>] (schedule+0x50/0xa8)
Sep 12 02:19:54 frida kernel: [13760.542871] [<c06d0b24>] (schedule) from [<c06d4260>] (schedule_timeout+0x1c8/0x394)
Sep 12 02:19:54 frida kernel: [13760.542893] [<c06d4260>] (schedule_timeout) from [<c06d1610>] (wait_for_common+0xac/0x178)
Sep 12 02:19:54 frida kernel: [13760.542914] [<c06d1610>] (wait_for_common) from [<c06d16fc>] (wait_for_completion+0x20/0x24)
Sep 12 02:19:54 frida kernel: [13760.542937] [<c06d16fc>] (wait_for_completion) from [<c0554344>] (rpi_firmware_transaction+0x6c/0xcc)
Sep 12 02:19:54 frida kernel: [13760.542955] [<c0554344>] (rpi_firmware_transaction) from [<c05544c0>] (rpi_firmware_property_list+0x11c/0x280)
Sep 12 02:19:54 frida kernel: [13760.542972] [<c05544c0>] (rpi_firmware_property_list) from [<c0554698>] (rpi_firmware_property+0x74/0xf8)
Sep 12 02:19:54 frida kernel: [13760.542993] [<c0554698>] (rpi_firmware_property) from [<c052c3a4>] (bcm2835_cpufreq_clock_property.constprop.1+0x54/0x80)
Sep 12 02:19:54 frida kernel: [13760.543015] [<c052c3a4>] (bcm2835_cpufreq_clock_property.constprop.1) from [<c052c41c>] (bcm2835_cpufreq_driver_target_index+0x4c/0xd8)
Sep 12 02:19:54 frida kernel: [13760.543035] [<c052c41c>] (bcm2835_cpufreq_driver_target_index) from [<c05280cc>] (__cpufreq_driver_target+0x2c4/0x5d4)
Sep 12 02:19:54 frida kernel: [13760.543051] [<c05280cc>] (__cpufreq_driver_target) from [<c052ad60>] (od_dbs_update+0xa8/0x170)
Sep 12 02:19:54 frida kernel: [13760.543069] [<c052ad60>] (od_dbs_update) from [<c052b9bc>] (dbs_work_handler+0x38/0x60)
Sep 12 02:19:54 frida kernel: [13760.543099] [<c052b9bc>] (dbs_work_handler) from [<c003d248>] (process_one_work+0x130/0x3a0)
Sep 12 02:19:54 frida kernel: [13760.543120] [<c003d248>] (process_one_work) from [<c003d4ec>] (worker_thread+0x34/0x530)
Sep 12 02:19:54 frida kernel: [13760.543139] [<c003d4ec>] (worker_thread) from [<c0042ff0>] (kthread+0x11c/0x158)
Sep 12 02:19:54 frida kernel: [13760.543157] [<c0042ff0>] (kthread) from [<c00090ac>] (ret_from_fork+0x14/0x28)
Sep 12 02:19:54 frida kernel: [13760.543167] Exception stack(0xcad27fb0 to 0xcad27ff8)
Sep 12 02:19:54 frida kernel: [13760.543177] 7fa0:                                     00000000 00000000 00000000 00000000
Sep 12 02:19:54 frida kernel: [13760.543190] 7fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Sep 12 02:19:54 frida kernel: [13760.543202] 7fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Sep 12 02:19:54 frida kernel: [13760.543215] INFO: task kworker/0:2:1660 blocked for more than 120 seconds.
Sep 12 02:19:54 frida kernel: [13760.543223]       Tainted: G         C        4.19.66+ #1253
Sep 12 02:19:54 frida kernel: [13760.543227] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 12 02:19:54 frida kernel: [13760.543232] kworker/0:2     D    0  1660      2 0x00000000
Sep 12 02:19:54 frida kernel: [13760.543270] Workqueue: events get_values_poll [raspberrypi_hwmon]
Sep 12 02:19:54 frida kernel: [13760.543301] [<c06d0648>] (__schedule) from [<c06d0b24>] (schedule+0x50/0xa8)
Sep 12 02:19:54 frida kernel: [13760.543321] [<c06d0b24>] (schedule) from [<c06d0e1c>] (schedule_preempt_disabled+0x18/0x1c)
Sep 12 02:19:54 frida kernel: [13760.543342] [<c06d0e1c>] (schedule_preempt_disabled) from [<c06d1d7c>] (__mutex_lock.constprop.5+0x110/0x33c)
Sep 12 02:19:54 frida kernel: [13760.543360] [<c06d1d7c>] (__mutex_lock.constprop.5) from [<c06d20c0>] (__mutex_lock_slowpath+0x1c/0x20)
Sep 12 02:19:54 frida kernel: [13760.543375] [<c06d20c0>] (__mutex_lock_slowpath) from [<c06d211c>] (mutex_lock+0x58/0x5c)
Sep 12 02:19:54 frida kernel: [13760.543392] [<c06d211c>] (mutex_lock) from [<c0554324>] (rpi_firmware_transaction+0x4c/0xcc)
Sep 12 02:19:54 frida kernel: [13760.543408] [<c0554324>] (rpi_firmware_transaction) from [<c05544c0>] (rpi_firmware_property_list+0x11c/0x280)
Sep 12 02:19:54 frida kernel: [13760.543425] [<c05544c0>] (rpi_firmware_property_list) from [<c0554698>] (rpi_firmware_property+0x74/0xf8)
Sep 12 02:19:54 frida kernel: [13760.543445] [<c0554698>] (rpi_firmware_property) from [<bf2580b8>] (get_values_poll+0x44/0x15c [raspberrypi_hwmon])
Sep 12 02:19:54 frida kernel: [13760.543471] [<bf2580b8>] (get_values_poll [raspberrypi_hwmon]) from [<c003d248>] (process_one_work+0x130/0x3a0)
Sep 12 02:19:54 frida kernel: [13760.543491] [<c003d248>] (process_one_work) from [<c003d4ec>] (worker_thread+0x34/0x530)
Sep 12 02:19:54 frida kernel: [13760.543508] [<c003d4ec>] (worker_thread) from [<c0042ff0>] (kthread+0x11c/0x158)
Sep 12 02:19:54 frida kernel: [13760.543524] [<c0042ff0>] (kthread) from [<c00090ac>] (ret_from_fork+0x14/0x28)
Sep 12 02:19:54 frida kernel: [13760.543531] Exception stack(0xcadfdfb0 to 0xcadfdff8)
Sep 12 02:19:54 frida kernel: [13760.543542] dfa0:                                     00000000 00000000 00000000 00000000
Sep 12 02:19:54 frida kernel: [13760.543553] dfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Sep 12 02:19:54 frida kernel: [13760.543564] dfe0: 00000000 00000000 00000000 00000000 00000013 00000000

Additional context With Raspbian Jessie with the same hardware environment and similar software environment everything worked fine for more than a year with month long uptimes.

MateEke commented 5 years ago

Same issue after rpi-update

pelwell commented 5 years ago

When you get this failure, try running vcgencmd commands to see if the VPU is still responsive.

MateEke commented 5 years ago

I have encountered the issue again. Fresh raspinfo output with the relevant dmesg output: pastebin

@pelwell 

pi@frida:~ $ vcgencmd commands
commands="vcos, ap_output_control, ap_output_post_processing, vchi_test_init, vchi_test_exit, vctest_memmap, vctest_start, vctest_stop, vctest_set, vctest_get, pm_set_policy, pm_get_status, pm_show_stats, pm_start_logging, pm_stop_logging, version, commands, set_vll_dir, set_backlight, set_logging, get_lcd_info, arbiter, cache_flush, otp_dump, test_result, codec_enabled, get_camera, get_mem, measure_clock, measure_volts, scaling_kernel, scaling_sharpness, get_hvs_asserts, get_throttled, measure_temp, get_config, hdmi_ntsc_freqs, hdmi_adjust_clock, hdmi_status_show, hvs_update_fields, pwm_speedup, force_audio, hdmi_stream_channels, hdmi_channel_map, display_power, read_ring_osc, memtest, dispmanx_list, get_rsts, schmoo, render_bar, disk_notify, inuse_notify, sus_suspend, sus_status, sus_is_enabled, sus_stop_test_thread, egl_platform_switch, mem_validate, mem_oom, mem_reloc_stats, hdmi_cvt, hdmi_timings, file"
pi@frida:~ $ vcgencmd dispmanx_list
display:2 format:XRGB8888 transform:0 layer:-127 1366x768 src:0,0,1366,768 dst:0,0,1366,768 cost:848 lbm:0
display:2 format:RGB565 transform:20000 layer:1 1366x768 src:0,0,1366,768 dst:0,0,1366,768 cost:658 lbm:0

I have tried the mentioned over_voltage=4 solution, but nothing changed.

Everything what not uses video works just fine after the error, except reboot and poweroff, they stuck at reached target reboot/poweroff.

pelwell commented 5 years ago

That's good, because a crashed VPU would be hard to debug.

This isn't really my field, so excuse any fuzzy terminology:

  1. Is your app synchronised to vsync?

  2. Is your app paced in some other way?

  3. Can you measure the time taken to submit an update (if it is synchronous), and the time between submission and display (if available), and watch for trends over time?

MateEke commented 5 years ago

That's good, because a crashed VPU would be hard to debug.

This isn't really my field, so excuse any fuzzy terminology:

  1. Is your app synchronised to vsync?
  2. Is your app paced in some other way?

I have found this after quick google search QT5 embedded linux. It's not clear for me if QT with EGLFS is synchronised to vsync or not, but as I understand it is. However it is a QT quick app with PyQT 5 and one QML file. I can provide the source if it helps.

  1. Can you measure the time taken to submit an update (if it is synchronous), and the time between submission and display (if available), and watch for trends over time?

I don't know how to do it, but I'm willing to help in any way if someone can provide a method.

pelwell commented 5 years ago

QT Quick looks pretty high-level, with the framework managing the render loop. This brief description suggests enabling some extra logging - does this look like something that can be added to your app?:

QLoggingCategory::setFilterRules("qt.scenegraph.general=true");
MateEke commented 5 years ago

QT Quick looks pretty high-level, with the framework managing the render loop. This brief description suggests enabling some extra logging - does this look like something that can be added to your app?:

QLoggingCategory::setFilterRules("qt.scenegraph.general=true");

I will try to set it trough env variable - QT doc export QT_LOGGING_RULES="*.debug=false;driver.usb.debug=true;qt.scenegraph.general=true"

EDIT

As I see QLoggingCategory is implemented in PyQT5 so I can add this to the app too. I will try when I get home because after the crash I can't restart the app or reboot the device trough SSH...

MateEke commented 5 years ago 
qt.scenegraph.general: threaded render loop
qt.scenegraph.general: Using sg animation driver
qt.scenegraph.general: Animation Driver: using vsync: 16.67 ms
qt.scenegraph.general: Using sg animation driver
qt.scenegraph.general: Animation Driver: using vsync: 16.67 ms
qt.scenegraph.general: texture atlas dimensions: 2048x1024
qt.scenegraph.general: R/G/B/A Buffers:   5 6 5 0
qt.scenegraph.general: Depth Buffer:      24
qt.scenegraph.general: Stencil Buffer:    8
qt.scenegraph.general: Samples:           0
qt.scenegraph.general: GL_VENDOR:         Broadcom
qt.scenegraph.general: GL_RENDERER:       VideoCore IV HW
qt.scenegraph.general: GL_VERSION:        OpenGL ES 2.0
qt.scenegraph.general: GL_EXTENSIONS:     GL_APPLE_rgb_422 GL_EXT_debug_marker GL_EXT_discard_framebuffer GL_EXT_texture_format_BGRA8888 GL_OES_EGL_image GL_OES_EGL_image_external GL_OES_compressed_ETC1_RGB8_texture GL_OES_compressed_paletted_texture GL_OES_depth24 GL_OES_depth32 GL_OES_mapbuffer GL_OES_rgb8_rgba8 GL_OES_texture_npot GL_OES_vertex_half_float
qt.scenegraph.general: Max Texture Size: 2048
qt.scenegraph.general: Debug context:    false
pelwell commented 5 years ago

So that works - cool.

Try doing the same with qt.scenegraph.renderloop=true. I'm hoping for something with timestamps. If that output doesn't look so useful, try qt.scenegraph.time.renderloop=true, or perhaps both.

pelwell commented 5 years ago

It might also helpful to know how frequently the screen changes and the pattern of changes. For example, for a digital picture frame one might expect a largely static screen, perhaps with a clock that changes sometimes, and with animated transitions between the images.

MateEke commented 5 years ago

qt.scenegraph.renderloop generates huge logs: pastebin maybe qt.scenegraph.time.renderloop would be enough?

Here is a screenshot. Top right corner clock updates every seconds, the temperature and the icon below that updates every 5 minutes. Bottom left corner updates in every minute. The image changes every 2 minutes with a fade-in fade-out effect.

Jegyzet 2019-09-17 174832

pelwell commented 5 years ago

qt.scenegraph.time.renderloop on its own looks promising. Try grabbing a few minutes like that, and if the output looks like it might be manageable over a few hours allow it to run until it fails.

MateEke commented 5 years ago

now it looks like this:

Sep 17 18:07:48 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 2ms, sync=0, render=1, swap=0 - (on render thread)
Sep 17 18:07:48 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=7, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:49 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:49 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 11ms, sync=1, render=2, swap=8 - (on render thread)
Sep 17 18:07:50 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:50 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:07:51 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:51 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:07:52 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:52 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:07:53 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:53 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:07:54 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=2, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:54 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 9ms, sync=1, render=7, swap=1 - (on render thread)
Sep 17 18:07:55 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:55 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:07:56 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:56 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:07:57 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:57 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 11ms, sync=1, render=2, swap=8 - (on render thread)
Sep 17 18:07:58 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:07:58 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:07:59 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 3ms, sync=1, render=1, swap=0 - (on render thread)
Sep 17 18:07:59 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=13, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:00 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:00 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:08:01 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 2ms, sync=0, render=1, swap=0 - (on render thread)
Sep 17 18:08:01 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=7, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:02 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:02 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 15ms, sync=1, render=2, swap=12 - (on render thread)
Sep 17 18:08:03 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:03 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:08:04 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:04 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:08:05 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:05 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:08:06 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:06 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 11ms, sync=1, render=2, swap=8 - (on render thread)
Sep 17 18:08:07 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:07 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:08:08 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 2ms, sync=0, render=1, swap=0 - (on render thread)
Sep 17 18:08:08 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=7, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:09 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:09 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:08:10 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:10 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:08:11 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:11 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:08:12 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:12 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:08:13 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:13 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:08:14 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:14 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 10ms, sync=1, render=2, swap=7 - (on render thread)
Sep 17 18:08:15 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:15 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:08:16 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:16 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)
Sep 17 18:08:17 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:17 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 12ms, sync=1, render=2, swap=9 - (on render thread)
Sep 17 18:08:18 frida systemd[1]: systemd-hostnamed.service: Succeeded.
Sep 17 18:08:18 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 2ms, sync=0, render=1, swap=0 - (on render thread)
Sep 17 18:08:18 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=7, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:19 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 2ms, sync=0, render=1, swap=0 - (on render thread)
Sep 17 18:08:19 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=9, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:20 frida python3[374]: qt.scenegraph.time.renderloop: Frame prepared with 'threaded' renderloop, polish=0, lock=0, blockedForSync=3, animations=0 - (on Gui thread) QQuickApplicationWindow_QML_2(0x1a086b0 active exposed, visibility=QWindow::FullScreen, flags=QFlags<Qt::WindowType>(Window), title="DigitalPictureFrame", geometry=0,0 1366x768)
Sep 17 18:08:20 frida python3[374]: qt.scenegraph.time.renderloop: Frame rendered with 'threaded' renderloop in 13ms, sync=1, render=2, swap=10 - (on render thread)

I'll let it run until it fails. The longest time was 2 days, the shortest only 2-3 hours.

MateEke commented 5 years ago

And here it is. The latest state of the clock is '02:16:33' log from 02:15:15 to 02:27:46 (last kworker exception log): pastebin there are no qt.scenegraph.time.renderloop logs after '02:16:33'

pelwell commented 5 years ago

Thanks - that's very interesting. I thought I might see a gradually slowing down, but that doesn't seem to be the case. What I do see is the final 'Frame prepared' at 02:16:36, followed by CRON starting at 02:17:01.

Could you grab another log like that? A slightly longer trace before the first failure would be ideal if possible.

MateEke commented 5 years ago

Could you grab another log like that? A slightly longer trace before the first failure would be ideal if possible.

I can. I kept the log for this failure, so I can send a longer version of it. How long?

pelwell commented 5 years ago

All of it (unless you are paying for the extra bytes)? You should be able to attach it to this issue.

MateEke commented 5 years ago

From midnight (logrotate) to 8 am syslog_09_18.txt From 09.17 18:14 to midnight syslog_09_17.zip

MateEke commented 4 years ago

I have made an observation. My program have a part, which blanks the screen if there is no motion detected over bluetooth in the past 20 minutes - it runs vcgencmd display_power 0. Accidentally I have messed up this part in the program, so the screen was continuously turned on for three days. I have not encountered the kernel error during this three days. As I remember (not sure) the kernel error always appeared when the screen was turned off.

EDIT:

Here we go again. Yesterday evening I have fixed the motion detection part, so this night the display turned off. Sep 23 00:14:32 frida python3[395]: display_power=0. The screen freezed at 02:13:14. Logs from yesterday (I have fixed the motion detection and rebooted around 6 pm): syslog_09_22.zip Logs from today: syslog_09_23.zip

carlonluca commented 4 years ago

Hello! Sorry to disturb, I just want to notify that I encountered the same problem. I'm using Qt on eglfs fkms (Qt 5.12.4). These are the logs I can read: https://pastebin.com/K6rhXkcR. Software remains in the defunct state once killed. If I try to restart, I get:

[245656.791010] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [CRTC:49:crtc-0] flip_done timed out
[245667.031008] [drm:drm_atomic_helper_wait_for_dependencies [drm_kms_helper]] *ERROR* [PLANE:28:plane-0] flip_done timed out

Screen was off during the test. I'll run other tests.

MateEke commented 4 years ago

Another freeze with disabled screen. Sep 24 08:45:33 frida python3[394]: display_power=0 Sep 24 14:18:06 frida kernel: [56522.982814] INFO: task kworker/0:1:3180 blocked for more than 120 seconds. Full log: syslog_09_24.zip

I will try hdmi_force_hotplug=1 but I don't think this will solve this issue.

6by9 commented 4 years ago

@carlonluca Sorry, not relevant to this issue which is a Pi0 and running bcm2708_fb (not FKMS or KMS).

The symptom of "blocked for more than 120 seconds." in a rpi_firmware_transaction call just means that the firmware mailbox service has stopped responding, quite possibly because something has gone wrong in servicing a previous request. Very few mailbox calls block so more than a few 10s of ms, the main one I can think of being HDMI mode switching under FKMS which takes around 6 frames or ~100ms.

DRM's *ERROR* [CRTC:49:crtc-0] flip_done timed out error means that it has submitted a screen update and not had a vsync or other completion callback to say that the screen flip has completed within the (default 10second) timeout.

carlonluca commented 4 years ago

The stack was quite similar. Are you saying these may not be related? Do you think I should open a different report? Thanks.

6by9 commented 4 years ago

Do you think I should open a different report?

Yes please if you have a reproducable test case.

As in my previous comment the stack trace just means that the VPU mailbox service has stopped responding for some reason. The trigger for that failure may be the same, but I doubt it in this case as you are using very different graphics stacks.

MateEke commented 4 years ago

I will try hdmi_force_hotplug=1 but I don't think this will solve this issue.

No freeze since I set hdmi_force_hotplug=1. Seems like viable workaround.

susron commented 4 years ago

I wrote an app importing :

from PyQt5.QtGui import QPixmap
from PyQt5.QtCore import QTimer, pyqtSlot, QObject, pyqtSignal

Raspberry Pi 4 Qt version: 5.11.3 SIP version: 4.19.14 PyQt version: 5.11.3

Which does the same freeze in the 2->12 hour range This same application runs flawlessly on a Raspberry PI 3b

**INFO: task kworker/0:0:5183 blocked for more than 120 seconds.
Tainted: G         C        4.19.66-v7l+ #1253**

And exactly the same error on another later kernel : 4.19.75-v7l+ #1270

My screen is never disabled and is on permanently. Adding force hdmi_force_hotplug=1 made no difference.